BW is miscalculated for jobs linked with "wait_for"

[yurzo]

This is the result of 6 jobs all chained with "wait_for" so only one executes at a given time. the rate is limited to 1024MiB/s
The total io seems correct. The time seems to be the time for one job in the group rather than the aggregate time for the target file.

Run status group 0 (all jobs):
  WRITE: bw=6146MiB/s (6445MB/s), 6146MiB/s-6146MiB/s (6445MB/s-6445MB/s), io=216GiB (232GB), run=35988-35988msec

[sitsofe]

@yurzo you didn't include the fio command line (and job file) you were running (as requested over in
https://github.com/axboe/fio/blob/fio-3.3/REPORTING-BUGS ). I'm going to guess you were using group_reporting=1 and if so that's why you see the result you do. "run=35988-35988msec" is telling you the minimum of and maximum of all the times component jobs took to run not the sum total time (see the run heading over in http://fio.readthedocs.io/en/latest/fio_doc.html#interpreting-the-output for another explanation).

[axboe]

There's plenty of room for improvement in the ETA calculation for jobs with stonewall/wait_for dependencies. Actually, there's a lot of room in general... Would be nice to improve that. Should really be abstracted out into a single function that calculates how much time it will take for a job to run. Sometimes that's possible (like if it has a fixed runtime, or a fixed size and rate), sometimes it is not. For multiple jobs, whether they run in parallel or are serialized can then be factored into to make a better guess.

So this is mostly a known issue, but nobody has attempted to tackle it yet.

[axboe]

eta.c:thread_eta() actually looks like it factors in most of these already, so I bet the main missing piece is just whether for X threads the time is serialized or parallelized.

[axboe]

That is also there, so there's some bug related to it. I'll take a look when I have time. For reference, here's a simple job that shows the issue:

[global]
bs=4k
rw=randread
norandommap
size=1t
direct=1
ioengine=null

[job1]
runtime=5s

[job2]
wait_for=job1
runtime=5s

[job3]
wait_for=job2
runtime=5s

[job4]
wait_for=job3
runtime=5s

Clearly, this will run for 20 seconds, since each of the 5 second jobs are serialized. If you look at ETA output while it's running, it's confused.

[yurzo]

@sitsofe
Reading the pointer you sent:

Run status group 0 (all jobs):
  WRITE: bw=6146MiB/s (6445MB/s), 6146MiB/s-6146MiB/s (6445MB/s-6445MB/s), io=216GiB (232GB), run=35988-35988msec

io is correct
run is correct (can't comment on @axboe's experiment)

I think the BW calculation is wrong.

Seems to be dividing the total io over the thread-or-job time. Rather than the thread-or-job io over the the thread-or-job time.

I'm going to go browse the code now.

bw
    Aggregate bandwidth of threads in this group followed by the minimum and maximum bandwidth of all the threads in this group. Values outside of brackets are power-of-2 format and those within are the equivalent value in a power-of-10 format.```

[yurzo]

I think this is the bug:

void sum_group_stats(struct group_run_stats *dst, struct group_run_stats *src)
{
        int i;

        for (i = 0; i < DDIR_RWDIR_CNT; i++) {
                if (dst->max_run[i] < src->max_run[i])
                        dst->max_run[i] = src->max_run[i];
                if (dst->min_run[i] && dst->min_run[i] > src->min_run[i])
                        dst->min_run[i] = src->min_run[i];
                if (dst->max_bw[i] < src->max_bw[i])
                        dst->max_bw[i] = src->max_bw[i];
                if (dst->min_bw[i] && dst->min_bw[i] > src->min_bw[i])
                        dst->min_bw[i] = src->min_bw[i];

                dst->iobytes[i] += src->iobytes[i];
                dst->agg[i] += src->agg[i];
        }

        if (!dst->kb_base)
                dst->kb_base = src->kb_base;
        if (!dst->unit_base)
                dst->unit_base = src->unit_base;
}

dst->agg[i] += src->agg[i];

The sum of bandwidths is not the aggregate bandwidth in this case because the threads are not executing at the same time.
I need to think how could I fix this without breaking it for the more general case

[yurzo]

This to repro:

[global]
bs=4k
rw=randread
norandommap
size=1t
direct=1
ioengine=null
group_reporting=1

[job1]
runtime=5s
rate=1073741824,1073741824,1073741824
[job2]
wait_for=job1
runtime=5s
rate=1073741824,1073741824,1073741824
[job3]
wait_for=job2
runtime=5s
rate=1073741824,1073741824,1073741824
[job4]
wait_for=job3
runtime=5s
rate=1073741824,1073741824,1073741824

Output:

Run status group 0 (all jobs):
   READ: bw=4095MiB/s (4294MB/s), 4095MiB/s-4095MiB/s (4294MB/s-4294MB/s), io=20.0GiB (21.5GB), run=5001-5001msec

[sitsofe]

The fix would be to take total I/O done then work out the the time period from when the first job started to when the last job finished. Divide the total I/O done by the previously calculated period and you have the average bandwidth over the group run. If the jobs are running concurrently this should give a similar result to before. There's are few difficulties though:

Jobs have periods when they that shouldn't be counted (startdelay, ramp_time) so we have to discount them. To do this we need the time that each job finishes (since we have the runtime and the periods that don't count are always prior to that). I'd say just use the wall clock but I'm not sure how this works when you have a client/server setup and you can't trust the servers to have in-sync clocks...

Also will this change confuse people? If I have job1 and job2 where job2 only runs when job1 is finished and both run for 5 seconds, if job1 achieves a bandwidth 500 Mbytes/s and job2 achieves a bandwidth of 0 will people be OK with being told the aggregate bandwidth was 250 Mbytes/s?