numjobs >1, groupreporting, json output metrics inconsistency

[brycepg]

Issue: It's not clear which metrics are per job and which are for a group of jobs.

Using numjobs>1, groupreporting set, with output-format=json I've noticed that some metrics report a value for a job group, and other values are divided by the number of jobs.

For example, for a purely write workload with numjobs=4, My write["iops"] is 25345 but my "iops_mean" is 6334. For this specific workload, these numbers should be the same since it is a write-only workload.

25345/6334 is approximately 4, which is the number of numjobs, so I can see where the discrepancy lies. This issue also applies to iops_stddev.

cli-args

fio reporting-issue.txt --output-format=json+ --output=out.out

reporting-issues.txt jobfile

[global]
name=R4K
group_reporting=1
per_job_logs=1
ioengine=libaio
randrepeat=0
direct=1
bs=4k
iodepth=1
numjobs=4
rw=randrw
rwmixread=0.0
percentage_random=100
time_based
runtime=5
[j1]
filename=/dev/sdb

out.out

{
  "fio version" : "fio-3.3-dirty",
  "timestamp" : 1516921576,
  "timestamp_ms" : 1516921576060,
  "time" : "Thu Jan 25 16:06:16 2018",
  "global options" : {
    "name" : "R4K",
    "group_reporting" : "1",
    "per_job_logs" : "1",
    "ioengine" : "libaio",
    "randrepeat" : "0",
    "direct" : "1",
    "bs" : "4k",
    "iodepth" : "1",
    "rw" : "randrw",
    "rwmixread" : "0.0",
    "percentage_random" : "100",
    "runtime" : "5"
  },
  "jobs" : [
    {
      "jobname" : "j1",
      "groupid" : 0,
      "error" : 0,
      "eta" : 0,
      "elapsed" : 6,
      "job options" : {
        "filename" : "/dev/sdb"
      },
      "read" : {
        "io_bytes" : 0,
        "io_kbytes" : 0,
        "bw_bytes" : 0,
        "bw" : 0,
        "iops" : 0.000000,
        "runtime" : 0,
        "total_ios" : 0,
        "short_ios" : 0,
        "drop_ios" : 0,
        "slat_ns" : {
          "min" : 0,
          "max" : 0,
          "mean" : 0.000000,
          "stddev" : 0.000000
        },
        "clat_ns" : {
          "min" : 0,
          "max" : 0,
          "mean" : 0.000000,
          "stddev" : 0.000000,
          "percentile" : {
            "1.000000" : 0,
            "5.000000" : 0,
            "10.000000" : 0,
            "20.000000" : 0,
            "30.000000" : 0,
            "40.000000" : 0,
            "50.000000" : 0,
            "60.000000" : 0,
            "70.000000" : 0,
            "80.000000" : 0,
            "90.000000" : 0,
            "95.000000" : 0,
            "99.000000" : 0,
            "99.500000" : 0,
            "99.900000" : 0,
            "99.950000" : 0,
            "99.990000" : 0,
            "0.00" : 0,
            "0.00" : 0,
            "0.00" : 0
          },
          "bins" : {

          }
        },
        "lat_ns" : {
          "min" : 0,
          "max" : 0,
          "mean" : 0.000000,
          "stddev" : 0.000000
        },
        "bw_min" : 0,
        "bw_max" : 0,
        "bw_agg" : 0.000000,
        "bw_mean" : 0.000000,
        "bw_dev" : 0.000000,
        "bw_samples" : 0,
        "iops_min" : 0,
        "iops_max" : 0,
        "iops_mean" : 0.000000,
        "iops_stddev" : 0.000000,
        "iops_samples" : 0
      },
      "write" : {
        "io_bytes" : 519172096,
        "io_kbytes" : 507004,
        "bw_bytes" : 103813656,
        "bw" : 101380,
        "iops" : 25345.130974,
        "runtime" : 5001,
        "total_ios" : 126751,
        "short_ios" : 0,
        "drop_ios" : 0,
        "slat_ns" : {
          "min" : 3474,
          "max" : 63815,
          "mean" : 5976.586757,
          "stddev" : 4148.390524
        },
        "clat_ns" : {
          "min" : 59875,
          "max" : 314670,
          "mean" : 149191.502978,
          "stddev" : 11738.405768,
          "percentile" : {
            "1.000000" : 122368,
            "5.000000" : 129536,
            "10.000000" : 132096,
            "20.000000" : 140288,
            "30.000000" : 146432,
            "40.000000" : 146432,
            "50.000000" : 148480,
            "60.000000" : 150528,
            "70.000000" : 154624,
            "80.000000" : 156672,
            "90.000000" : 164864,
            "95.000000" : 168960,
            "99.000000" : 177152,
            "99.500000" : 179200,
            "99.900000" : 197632,
            "99.950000" : 203776,
            "99.990000" : 220160,
            "0.00" : 0,
            "0.00" : 0,
            "0.00" : 0
          },
          "bins" : {
            "59648" : 1,
            "67072" : 1,
            "68096" : 1,
            "70144" : 1,
            "78336" : 1,
            "80384" : 1,
            "81408" : 2,
            "82432" : 1,
            "87552" : 1,
            "88576" : 1,
            "89600" : 2,
            "90624" : 3,
            "91648" : 8,
            "92672" : 7,
            "93696" : 7,
            "94720" : 22,
            "95744" : 8,
            "96768" : 30,
            "97792" : 24,
            "98816" : 19,
            "99840" : 16,
            "100864" : 21,
            "101888" : 8,
            "102912" : 19,
            "103936" : 18,
            "104960" : 19,
            "105984" : 22,
            "107008" : 26,
            "108032" : 43,
            "109056" : 36,
            "110080" : 37,
            "111104" : 35,
            "112128" : 29,
            "113152" : 27,
            "114176" : 52,
            "115200" : 52,
            "116224" : 80,
            "117248" : 79,
            "118272" : 55,
            "119296" : 71,
            "120320" : 117,
            "121344" : 161,
            "122368" : 165,
            "123392" : 184,
            "124416" : 217,
            "125440" : 370,
            "126464" : 647,
            "127488" : 891,
            "128512" : 1589,
            "129536" : 2115,
            "130560" : 1444,
            "132096" : 3900,
            "134144" : 3129,
            "136192" : 2573,
            "138240" : 5831,
            "140288" : 4437,
            "142336" : 4147,
            "144384" : 4094,
            "146432" : 14328,
            "148480" : 14150,
            "150528" : 12256,
            "152576" : 10847,
            "154624" : 8322,
            "156672" : 5843,
            "158720" : 4525,
            "160768" : 2635,
            "162816" : 2293,
            "164864" : 3994,
            "166912" : 2768,
            "168960" : 2173,
            "171008" : 1848,
            "173056" : 1368,
            "175104" : 1226,
            "177152" : 635,
            "179200" : 174,
            "181248" : 88,
            "183296" : 56,
            "185344" : 43,
            "187392" : 29,
            "189440" : 28,
            "191488" : 29,
            "193536" : 40,
            "195584" : 28,
            "197632" : 21,
            "199680" : 19,
            "201728" : 14,
            "203776" : 18,
            "205824" : 7,
            "207872" : 11,
            "209920" : 10,
            "211968" : 3,
            "214016" : 7,
            "216064" : 4,
            "218112" : 1,
            "220160" : 1,
            "224256" : 2,
            "226304" : 1,
            "238592" : 2,
            "244736" : 1,
            "259072" : 1,
            "261120" : 1,
            "284672" : 1,
            "288768" : 1,
            "305152" : 1,
            "313344" : 1
          }
        },
        "lat_ns" : {
          "min" : 64187,
          "max" : 318749,
          "mean" : 155383.771970,
          "stddev" : 10147.643771
        },
        "bw_min" : 25120,
        "bw_max" : 25712,
        "bw_agg" : 24.994301,
        "bw_mean" : 25339.222222,
        "bw_dev" : 188.107129,
        "bw_samples" : 36,
        "iops_min" : 6280,
        "iops_max" : 6428,
        "iops_mean" : 6334.777778,
        "iops_stddev" : 47.026504,
        "iops_samples" : 36
      },
      "trim" : {
        "io_bytes" : 0,
        "io_kbytes" : 0,
        "bw_bytes" : 0,
        "bw" : 0,
        "iops" : 0.000000,
        "runtime" : 0,
        "total_ios" : 0,
        "short_ios" : 0,
        "drop_ios" : 0,
        "slat_ns" : {
          "min" : 0,
          "max" : 0,
          "mean" : 0.000000,
          "stddev" : 0.000000
        },
        "clat_ns" : {
          "min" : 0,
          "max" : 0,
          "mean" : 0.000000,
          "stddev" : 0.000000,
          "percentile" : {
            "1.000000" : 0,
            "5.000000" : 0,
            "10.000000" : 0,
            "20.000000" : 0,
            "30.000000" : 0,
            "40.000000" : 0,
            "50.000000" : 0,
            "60.000000" : 0,
            "70.000000" : 0,
            "80.000000" : 0,
            "90.000000" : 0,
            "95.000000" : 0,
            "99.000000" : 0,
            "99.500000" : 0,
            "99.900000" : 0,
            "99.950000" : 0,
            "99.990000" : 0,
            "0.00" : 0,
            "0.00" : 0,
            "0.00" : 0
          },
          "bins" : {

          }
        },
        "lat_ns" : {
          "min" : 0,
          "max" : 0,
          "mean" : 0.000000,
          "stddev" : 0.000000
        },
        "bw_min" : 0,
        "bw_max" : 0,
        "bw_agg" : 0.000000,
        "bw_mean" : 0.000000,
        "bw_dev" : 0.000000,
        "bw_samples" : 0,
        "iops_min" : 0,
        "iops_max" : 0,
        "iops_mean" : 0.000000,
        "iops_stddev" : 0.000000,
        "iops_samples" : 0
      },
      "usr_cpu" : 2.740000,
      "sys_cpu" : 5.910000,
      "ctx" : 126752,
      "majf" : 0,
      "minf" : 67,
      "iodepth_level" : {
        "1" : 100.000000,
        "2" : 0.000000,
        "4" : 0.000000,
        "8" : 0.000000,
        "16" : 0.000000,
        "32" : 0.000000,
        ">=64" : 0.000000
      },
      "latency_ns" : {
        "2" : 0.000000,
        "4" : 0.000000,
        "10" : 0.000000,
        "20" : 0.000000,
        "50" : 0.000000,
        "100" : 0.000000,
        "250" : 0.000000,
        "500" : 0.000000,
        "750" : 0.000000,
        "1000" : 0.000000
      },
      "latency_us" : {
        "2" : 0.000000,
        "4" : 0.000000,
        "10" : 0.000000,
        "20" : 0.000000,
        "50" : 0.000000,
        "100" : 0.119131,
        "250" : 99.876135,
        "500" : 0.010000,
        "750" : 0.000000,
        "1000" : 0.000000
      },
      "latency_ms" : {
        "2" : 0.000000,
        "4" : 0.000000,
        "10" : 0.000000,
        "20" : 0.000000,
        "50" : 0.000000,
        "100" : 0.000000,
        "250" : 0.000000,
        "500" : 0.000000,
        "750" : 0.000000,
        "1000" : 0.000000,
        "2000" : 0.000000,
        ">=2000" : 0.000000
      },
      "latency_depth" : 1,
      "latency_target" : 0,
      "latency_percentile" : 100.000000,
      "latency_window" : 0
    }
  ],
  "disk_util" : [
    {
      "name" : "sdb",
      "read_ios" : 41,
      "write_ios" : 123926,
      "read_merges" : 0,
      "write_merges" : 0,
      "read_ticks" : 18,
      "write_ticks" : 17848,
      "in_queue" : 17847,
      "util" : 98.018415
    }
  ]
}
j1: (groupid=0, jobs=4): err= 0: pid=1617: Thu Jan 25 16:06:16 2018
  write: IOPS=25.3k, BW=99.0MiB/s (104MB/s)(495MiB/5001msec)
    slat (nsec): min=3474, max=63815, avg=5976.59, stdev=4148.39
    clat (usec): min=59, max=314, avg=149.19, stdev=11.74
     lat (usec): min=64, max=318, avg=155.38, stdev=10.15
    clat percentiles (usec):
     |  1.00th=[  123],  5.00th=[  130], 10.00th=[  133], 20.00th=[  141],
     | 30.00th=[  147], 40.00th=[  147], 50.00th=[  149], 60.00th=[  151],
     | 70.00th=[  155], 80.00th=[  157], 90.00th=[  165], 95.00th=[  169],
     | 99.00th=[  178], 99.50th=[  180], 99.90th=[  198], 99.95th=[  204],
     | 99.99th=[  221]
   bw (  KiB/s): min=25120, max=25712, per=24.99%, avg=25339.22, stdev=188.11, samples=36
   iops        : min= 6280, max= 6428, avg=6334.78, stdev=47.03, samples=36
  lat (usec)   : 100=0.12%, 250=99.88%, 500=0.01%
  cpu          : usr=2.74%, sys=5.91%, ctx=126752, majf=0, minf=67
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=0,126751,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

[sitsofe]

This stems from where the values are calculated. If you look at summary line you have a write: row whose IOPS and BW values are the totals divided by time (which is currently assuming all jobs start and finish at the same time). Further down you have bw ( KiB/ s) and iops which are calculated by periodic sampling then averaging the samples (each job collects it's own samples). I'm guessing we are seeing the sample based data for only the first job. The question is does it make sense to aggregate sample data across jobs due to it not being per I/O information?

[jo-ale35]

In the json output for FIO with group reporting enabled
"read" : {
"io_bytes" : 1057615773696,
"io_kbytes" : 1032827904,
"bw_bytes" : 35252684033,
"bw" : 34426449,
"iops" : 134478.317389,
"runtime" : 30001,
"total_ios" : 4034484,
"lat_ns" : {
"min" : 15484,
"max" : 187915,
"mean" : 29530.916097,
"stddev" : 2120.677525
},
"bw_min" : 8321024,
"bw_max" : 8822272,
"bw_agg" : 24.996299,
"bw_mean" : 8605338.033898,
"bw_dev" : 116041.922648,
"bw_samples" : 236,
"iops_min" : 32504,
"iops_max" : 34462,
"iops_mean" : 33614.601695,
"iops_stddev" : 453.265666,
"iops_samples" : 236
},

As per our understanding the values we get in json output as bw_min,bw_max,bw_mean and bw_agg are per thread/job results and bw, iops etc. are the aggregated result of all threads/jobs.

But how can we achieve the aggregated result of all threads/jobs for max,min,mean values of bw and iops?
From the experiments that we have done we believe that the following formula can give us the aggregated result of all threads/jobs for max,min,mean values of bw and iops:

aggregated mean_bw=( bw_mean100)/bw_agg
aggregated max_bw=( bw_min*100)/bw_agg
aggregated max_bw=( bw_max*100)/bw_agg

aggregated mean_iops=( iops_mean100)/iops_agg
aggregated max_iops=( iops_min*100)/iops_agg
aggregated max_iops=( iops_max*100)/iops_agg

Is this the correct way to achieve those values?

And the latency output (lat_ns) is for per thread or for whole threads?
If it is for per thread, then in order to get the max,min and mean value for latency then we might require to do the above calculation for latency as well.

[sitsofe]

@jo-ale35 you'll have to check but I think the first set are the totals divided by time and the second set are due to periodic sampling on just one of the jobs. fio would need various bits of code rewritten if it we want it to be able to do periodic sampling of all the jobs in a group and it raises the question of what do you do if jobs have unequal numbers of samples in them / their sample periods don't overlap exactly.

I'm half tempted to say periodic sampling should just be turned off when group reporting is turned on.

[szaydel]

@sitsofe: I 100% agree with your assessment about periodic sampling. I also think with group reporting enabled, periodic sampling should be off.

[jo-ale35]

@sitsofe @szaydel Thanks for your inputs.

I am developing a graphical representation for fio results,I want three values minimum, maximum, and mean as the total of all the jobs run. The first part give me only one value that is mean bandwidth. So am using the above maths to get the three values, approx. values will be ok for me. Should I do same for latency values. Is latency values for periodic sampling on just one of the jobs or total of all the jobs.

[szaydel]

@jo-ale35, I think you can look at this from two different angles, one being statistical correctness, and the other being granularity. I feel like that statistically, it is hard to derive meaningful numbers by taking interval data from more than one job and treating each job equally. There is enough variability there to where I believe data will not necessarily be as meaningful. In my mind each job is an individual distribution and so say you have three jobs, each giving you a mean value, a max value and a min value for some variable X. Now the question I would ask is, do you just take the highest max and the lowest min out of these three, and then 1/N*sum(means), where N is 3 jobs, to compute the mean? This seems fairly sensible to do, assuming everything else about these jobs is identical. If you do this with interval data though, you are not guaranteed that number of samples will be same from each job, and each job will to some degree be influenced by how many samples were collected. Of course with interval samples you will have a mean for each job during given interval, and if you choose to take the same average I described earlier, you are potentially introducing difficult to realize biases into your data collection.

I think you should consider working with groups, and assuming you have multiple jobs all grouped into a single group, you should have no trouble using only summary data, not interval data as your source for visualization. This answer also depends on whether you care to report about individual jobs for some reason, in other words are all jobs going to be identical and are all of them going to be running at same time, or is there something more complex going on, like some partial overlap in jobs, resulting in some finishing sooner than others, or amount of IO done varying, or what the jobs themselves do, like different IO patterns, or different amount of IO, etc.

My knee-jerk reaction is to say that you are better off in most cases working with only the final data, which is processed for you and to some degree smoothed over each runtime, and if you need multiple samples, run the same job definitions over and over. From those results you can probably pull out averages or medians perhaps for each datapoint meaningful to you, like mean/min/max bandwidth, iops, etc.

[sitsofe]

The points from @szaydel really echo my thoughts too. I'm not a statistician but you have to be careful with how you start mixing sampled data together because if they are drawn from different distributions it's hard to use them together meaningfully. I see two approaches:

1. Run the jobs as a group and use the summary data.
2. Run the jobs separately with more detailed per I/O logging turned on and then post-process those results into what you're after. With full individual logs you can calculate whatever you like but the cost will be that the size of the logs will increase with the total number of I/Os that are performed.

Sam's earlier comment has encouraged me to look at whipping up a patch to just turn sampling off when using group reporting. When I've done it we'll see what Jens thinks.

[szaydel]

@sitsofe : thank you! :) I would also add that the shorter the jobs the fewer samples collected, the more likely there are to be really statistically impacting outliers in the interval data, and they could even further muddy waters. Conversely the longer the jobs are, the more the noise subsides. Length was not really mentioned here, so I am just raising it as another potential point to consider.

[jo-ale35]

@sitsofe @szaydel Thanks for all your inputs.This inputs will really help me to do my statistics required for the garph.

[universalbodge]

I got the same problem - see below IOPS and iops, having group_reporting specified, sampling numbers are really confusing - any plans to fix it?

rand-read-J4Q64: (groupid=26, jobs=4): err= 0: pid=22926: Thu Nov 29 19:50:03 2018
read: IOPS=165k, BW=643MiB/s (674MB/s)(3215MiB/5003msec)
bw ( KiB/s): min=120514, max=163298, per=19.61%, avg=129084.75, stdev=12317.14, samples=36
iops : min=30128, max=40824, avg=32270.69, stdev=3079.27, samples=36
cpu : usr=4.99%, sys=13.61%, ctx=545204, majf=0, minf=4
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=100.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.1%, >=64=0.0%
issued rwts: total=823160,0,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=64

[sitsofe]

@universalbodge As just another member of the community I've no plans to tackle this any time soon and as fio is a community project it doesn't really have a roadmap...

If I were to "fi" this I would likely just remove the sample data when group reporting were turned on but if you've created a good fix for this please submit a patch for review!

[axboe]

I can see how that would be confusing, it's a quick fix - which I've now committed.