Looks like when we set log_avg_msec=4000 or less it works as expected. Also, the logged timestamps are very close to 4000 multiples. When we set log_avg_msec=5000 or more the average is wrong, and also the logged timestamp has significant jitter from 5000 multiples. Are we overflowing the log_avg_msec variable (32bits)? Regards, Jeff -----Original Message----- From: fio-owner@xxxxxxxxxxxxxxx [mailto:fio-owner@xxxxxxxxxxxxxxx] On Behalf Of Gruher, Joseph R Sent: Monday, August 21, 2017 11:11 AM To: neto from Brazil <Antonio.Jose.Rodrigues.Neto@xxxxxxxxxx>; fio@xxxxxxxxxxxxxxx Subject: RE: IOPS Log Incorrect? Feature seems to work in FIO 2.15 through 2.20. I couldn't test 2.21 (keeps segfaulting when I try to run after compile) and then the feature is broken in the next release which is 2.99 and still broken in 3.0. > -----Original Message----- > From: Gruher, Joseph R > Sent: Thursday, August 17, 2017 5:16 PM > To: neto from Brazil <Antonio.Jose.Rodrigues.Neto@xxxxxxxxxx>; > fio@xxxxxxxxxxxxxxx > Subject: RE: IOPS Log Incorrect? > > This feature seems to work in FIO 2.15: > > root@nvmfjt01:/home/nvmf/jrg9/chandler# fio 4k-rr-01-01-128.ini > job00: (g=0): rw=randread, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, > iodepth=128 > fio-2.15 > Starting 1 thread > Jobs: 1 (f=1): [r(1)] [78.8% done] [1804MB/0KB/0KB /s] [462K/0/0 iops] > [eta 00m:58s] > job00: (groupid=0, jobs=1): err= 0: pid=5341: Thu Aug 17 16:57:40 2017 > read : io=277967MB, bw=1789.6MB/s, iops=457984, runt=155375msec > slat (usec): min=0, max=95, avg= 1.44, stdev= 0.91 > clat (usec): min=61, max=5168, avg=277.60, stdev=118.64 > lat (usec): min=62, max=5170, avg=279.12, stdev=118.63 > clat percentiles (usec): > | 1.00th=[ 129], 5.00th=[ 155], 10.00th=[ 173], 20.00th=[ 197], > | 30.00th=[ 215], 40.00th=[ 235], 50.00th=[ 255], 60.00th=[ 278], > | 70.00th=[ 306], 80.00th=[ 342], 90.00th=[ 406], 95.00th=[ 470], > | 99.00th=[ 636], 99.50th=[ 716], 99.90th=[ 1176], 99.95th=[ 2096], > | 99.99th=[ 2896] > lat (usec) : 100=0.12%, 250=47.54%, 500=48.64%, 750=3.31%, 1000=0.26% > lat (msec) : 2=0.08%, 4=0.05%, 10=0.01% > cpu : usr=28.43%, sys=68.46%, ctx=736888, majf=0, minf=816 > IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, > >=64=137.3% > 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.1% > issued : total=r=71159403/w=0/d=0, short=r=0/w=0/d=0, > drop=r=0/w=0/d=0 > latency : target=0, window=0, percentile=100.00%, depth=128 > Run status group 0 (all jobs): > READ: io=277967MB, aggrb=1789.6MB/s, minb=1789.6MB/s, > maxb=1789.6MB/s, mint=155375msec, maxt=155375msec Disk stats > (read/write): > nvme0n1: ios=97645100/0, merge=0/0, ticks=24504996/0, > in_queue=24519280, util=99.95% > > root@nvmfjt01:/home/nvmf/jrg9/chandler# cat joe1x128_iops.1.log 20001, > 438712, 0, 0 39999, 455544, 0, 0 59999, 457418, 0, 0 79999, 462500, 0, > 0 99999, 462728, 0, 0 119999, 462893, 0, 0 139999, 462508, 0, 0 > > root@nvmfjt01:/home/nvmf/jrg9/chandler# cat 4k-rr-01-01-128.ini > [global] bs=4k rw=randread > numjobs=1 > iodepth=128 > thread=1 > ioengine=libaio > direct=1 > ramp_time=60 > norandommap=1 > group_reporting=1 > write_iops_log=joe1x128 > log_avg_msec=20000 > [job00] > filename=/dev/nvme0n1 > > root@nvmfjt01:/home/nvmf/jrg9/chandler# uname -a Linux nvmfjt01 > 4.12.7- 041207-generic #201708160856 SMP Wed Aug 16 12:59:25 UTC 2017 > x86_64 > x86_64 x86_64 GNU/Linux > > root@nvmfjt01:/home/nvmf/jrg9/chandler# fio --version > fio-2.15 > > > -----Original Message----- > > From: Gruher, Joseph R > > Sent: Thursday, August 17, 2017 11:52 AM > > To: neto from Brazil <Antonio.Jose.Rodrigues.Neto@xxxxxxxxxx>; > > fio@xxxxxxxxxxxxxxx > > Subject: RE: IOPS Log Incorrect? > > > > Sure. That produces a very large log file where every entry is > > <timestamp>, 1, 0, 4096. See example below. > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# cat 4k-rr-01.ini [global] > > bs=4k rw=randread > > numjobs=1 > > iodepth=128 > > ioengine=libaio > > direct=1 > > runtime=3 > > write_iops_log=joe2 > > [job00] > > filename=/dev/nvme0n1 > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# fio 4k-rr-01.ini > > job00: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) > > 4096B- 4096B, ioengine=libaio, iodepth=128 > > fio-3.0 > > Starting 1 process > > Jobs: 1 (f=1): [r(1)][100.0%][r=1330MiB/s,w=0KiB/s][r=340k,w=0 > > IOPS][eta 00m:00s] > > job00: (groupid=0, jobs=1): err= 0: pid=3124: Thu Aug 17 11:49:47 2017 > > read: IOPS=317k, BW=1238MiB/s (1298MB/s)(3715MiB/3001msec) > > slat (nsec): min=930, max=114792, avg=2418.97, stdev=1970.30 > > clat (usec): min=81, max=1210, avg=400.22, stdev=74.26 > > lat (usec): min=84, max=1220, avg=402.75, stdev=74.53 > > clat percentiles (usec): > > | 1.00th=[ 310], 5.00th=[ 326], 10.00th=[ 334], 20.00th=[ 343], > > | 30.00th=[ 355], 40.00th=[ 363], 50.00th=[ 375], 60.00th=[ 392], > > | 70.00th=[ 420], 80.00th=[ 461], 90.00th=[ 494], 95.00th=[ 529], > > | 99.00th=[ 660], 99.50th=[ 734], 99.90th=[ 857], 99.95th=[ 889], > > | 99.99th=[ 1004] > > bw ( MiB/s): min= 960, max= 1332, per=98.62%, avg=1220.89, > >stdev=160.84, > > samples=5 > > iops : min= 1, max= 1, avg= 1.00, stdev= 0.00, samples=951085 > > lat (usec) : 100=0.01%, 250=0.05%, 500=91.24%, 750=8.28%, 1000=0.42% > > lat (msec) : 2=0.01% > > cpu : usr=22.13%, sys=77.87%, ctx=61, majf=0, minf=3234 > > IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, > >=64=99.9% > > 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.1% > > issued rwt: total=951085,0,0, short=0,0,0, dropped=0,0,0 > > latency : target=0, window=0, percentile=100.00%, depth=128 > > Run status group 0 (all jobs): > > READ: bw=1238MiB/s (1298MB/s), 1238MiB/s-1238MiB/s (1298MB/s- > > 1298MB/s), io=3715MiB (3896MB), run=3001-3001msec Disk stats > > (read/write): > > nvme0n1: ios=951085/0, merge=0/0, ticks=121124/0, in_queue=120984, > > util=92.50% > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# head -n 10 joe2_iops.1.log > > 2, 1, 0, > > 4096 2, 1, 0, 4096 2, 1, 0, 4096 2, 1, 0, 4096 2, 1, 0, 4096 2, 1, > > 0, > > 4096 2, 1, 0, > > 4096 2, 1, 0, 4096 2, 1, 0, 4096 2, 1, 0, 4096 > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# tail -n 10 joe2_iops.1.log > > 3000, 1, 0, 4096 3000, 1, 0, 4096 3000, 1, 0, 4096 3000, 1, 0, 4096 > > 3000, 1, 0, 4096 3000, 1, 0, 4096 3000, 1, 0, 4096 3000, 1, 0, 4096 > > 3000, 1, 0, 4096 3000, 1, 0, > > 4096 > > > > > > Thanks, > > Joe > > > > > -----Original Message----- > > > From: neto from Brazil > > > [mailto:Antonio.Jose.Rodrigues.Neto@xxxxxxxxxx] > > > Sent: Thursday, August 17, 2017 11:47 AM > > > To: Gruher, Joseph R <joseph.r.gruher@xxxxxxxxx>; > > > fio@xxxxxxxxxxxxxxx > > > Subject: Re: IOPS Log Incorrect? > > > > > > Hi Joseph, > > > > > > This is neto from Brazil > > > > > > How are you? > > > > > > Could you try to re-run without log_avg_msec=5000? > > > > > > Thanks, > > > > > > neto > > > > > > On 8/17/17, 2:38 PM, "fio-owner@xxxxxxxxxxxxxxx on behalf of > > > Gruher, Joseph R" <fio-owner@xxxxxxxxxxxxxxx on behalf of > > joseph.r.gruher@xxxxxxxxx> wrote: > > > > > > Hi, I'm using FIO 3.0 on Ubuntu 16.10 with 4.12.7 kernel (also > > > reproduced problem with default 4.8.0-59 kernel). I'm running a > > > 4KB random IO pattern against an Intel P3700 400GB NVMe SSD. I'm > > > trying to view the IOPS/BW over time using the write_bw_log and > > > write_iops_log parameters. FIO is writing the logs but the values > > > in the logs don't align with the summary for the run. Here's a > > > simple example. Notice FIO reports 398K IOPS for the run overall, > > > but the IOPS log file shows 383K for the first entry and then > > > values around 56K for the rest of the run, so > > one or the other must be incorrect (presumably the log file). > > > The bandwidth log has a similar issue. > > > > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# cat 4k-rr-01.ini > > > [global] > > > bs=4k > > > rw=randread > > > numjobs=1 > > > iodepth=128 > > > ioengine=libaio > > > direct=1 > > > runtime=30 > > > write_iops_log=joe2 > > > log_avg_msec=5000 > > > [job00] > > > filename=/dev/nvme0n1 > > > > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# fio 4k-rr-01.ini > > > job00: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) > > > 4096B-4096B, > > > (T) 4096B-4096B, ioengine=libaio, iodepth=128 > > > fio-3.0 > > > Starting 1 process > > > Jobs: 1 (f=1): [r(1)][100.0%][r=1595MiB/s,w=0KiB/s][r=408k,w=0 > > > IOPS][eta 00m:00s] > > > job00: (groupid=0, jobs=1): err= 0: pid=2767: Thu Aug 17 10:34:09 2017 > > > read: IOPS=398k, BW=1555MiB/s (1630MB/s)(45.6GiB/30001msec) > > > slat (nsec): min=824, max=117534, avg=1682.36, stdev=1290.45 > > > clat (usec): min=96, max=2899, avg=319.29, stdev=69.36 > > > lat (usec): min=97, max=2900, avg=321.08, stdev=69.39 > > > clat percentiles (usec): > > > | 1.00th=[ 221], 5.00th=[ 243], 10.00th=[ 255], 20.00th=[ 269], > > > | 30.00th=[ 281], 40.00th=[ 289], 50.00th=[ 302], 60.00th=[ 318], > > > | 70.00th=[ 334], 80.00th=[ 363], 90.00th=[ 412], 95.00th=[ 453], > > > | 99.00th=[ 562], 99.50th=[ 611], 99.90th=[ 725], 99.95th=[ 775], > > > | 99.99th=[ 906] > > > bw ( MiB/s): min= 1081, max= 1594, per=99.96%, avg=1554.11, > > > stdev=68.33, > > > samples=59 > > > iops : min=56293, max=383046, avg=65603.75, stdev=54419.77, > > samples=36 > > > lat (usec) : 100=0.01%, 250=7.73%, 500=89.82%, 750=2.38%, 1000=0.07% > > > lat (msec) : 2=0.01%, 4=0.01% > > > cpu : usr=32.51%, sys=67.50%, ctx=105, majf=0, minf=153 > > > 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.0%, > > > >=64=0.1% > > > issued rwt: total=11941208,0,0, short=0,0,0, dropped=0,0,0 > > > latency : target=0, window=0, percentile=100.00%, depth=128 > > > Run status group 0 (all jobs): > > > READ: bw=1555MiB/s (1630MB/s), 1555MiB/s-1555MiB/s (1630MB/s- > > > 1630MB/s), io=45.6GiB (48.9GB), run=30001-30001msec > > > Disk stats (read/write): > > > nvme0n1: ios=11890654/0, merge=0/0, ticks=1923076/0, > > > in_queue=1925204, util=99.69% > > > > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# cat joe2_iops.1.log > > > 5000, 383046, 0, 0 > > > 10640, 56412, 0, 0 > > > 15576, 56410, 0, 0 > > > 20511, 56425, 0, 0 > > > 25446, 56394, 0, 0 > > > 30040, 57131, 0, 0 > > > > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# fio --version > > > fio-3.0 > > > > > > > > > root@nvmfjt01:/home/nvmf/jrg9/chandler# uname -a > > > Linux nvmfjt01 4.12.7-041207-generic #201708160856 SMP Wed Aug > > > 16 > > > 12:59:25 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux > > > > > > -- > > > To unsubscribe from this list: send the line "unsubscribe fio" in > > > the body of a message to majordomo@xxxxxxxxxxxxxxx > > > More majordomo info at > > > http://vger.kernel.org/majordomo-info.html > > > {.n + +% lzwm b 맲 r y {ay ʇڙ ,j f h z w j:+v w j m zZ+ ݢj" ! i ��.n��������+%������w��{.n�������^n�r������&��z�ޗ�zf���h���~����������_��+v���)ߣ�
