Vincent On 21-Aug-17 18:30, Gruher, Joseph R wrote:
Yes! This seems to have fixed the issue. Thanks very much. Test results on 2.99 pasted below. nvmf@nvmfjt01:~/jrg9/chandler$ cat 4k-rr-01-01-128.ini |grep -v '#' [global] bs=4k rw=randread numjobs=1 iodepth=128 thread=1 ioengine=libaio direct=1 ramp_time=10 time_based=0 norandommap=1 write_iops_log=joe1x128map log_avg_msec=25000 [job00] filename=/dev/nvme0n1 nvmf@nvmfjt01:~/jrg9/chandler$ sudo fio 4k-rr-01-01-128.ini job00: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=128 fio-2.99 Starting 1 thread job00: No I/O performed by libaio, perhaps try --debug=io option for details?1s] job00: (groupid=0, jobs=1): err= 0: pid=12127: Mon Aug 21 15:27:02 2017 read: IOPS=391k, BW=1526MiB/s (1600MB/s)(357GiB/239570msec) slat (nsec): min=905, max=186037, avg=1767.28, stdev=1210.88 clat (usec): min=64, max=3207, avg=325.34, stdev=64.39 lat (usec): min=65, max=3208, avg=327.22, stdev=64.46 clat percentiles (usec): | 1.00th=[ 231], 5.00th=[ 251], 10.00th=[ 262], 20.00th=[ 277], | 30.00th=[ 289], 40.00th=[ 297], 50.00th=[ 310], 60.00th=[ 326], | 70.00th=[ 343], 80.00th=[ 367], 90.00th=[ 408], 95.00th=[ 449], | 99.00th=[ 545], 99.50th=[ 586], 99.90th=[ 701], 99.95th=[ 742], | 99.99th=[ 840] bw ( MiB/s): min= 1086, max= 1641, per=100.00%, avg=1537.14, stdev=88.71, samples=479 iops : min=353807, max=411848, avg=389345.11, stdev=17570.39, samples=9 lat (usec) : 100=0.01%, 250=4.85%, 500=93.10%, 750=2.01%, 1000=0.04% lat (msec) : 2=0.01%, 4=0.01% cpu : usr=31.05%, sys=68.96%, ctx=716, majf=0, minf=2121 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=104.4% 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=93588018,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=1526MiB/s (1600MB/s), 1526MiB/s-1526MiB/s (1600MB/s-1600MB/s), io=357GiB (383GB), run=239570-239570msec Disk stats (read/write): nvme0n1: ios=97644549/0, merge=0/0, ticks=15111756/0, in_queue=15145884, util=100.00% nvmf@nvmfjt01:~/jrg9/chandler$ cat joe1x128map_iops.1.log 24999, 386402, 0, 0 49997, 389145, 0, 0 74996, 382756, 0, 0 99995, 387607, 0, 0 124994, 381998, 0, 0 149992, 353807, 0, 0 174991, 398791, 0, 0 200000, 411848, 0, 0 225000, 411752, 0, 0-----Original Message----- From: Sitsofe Wheeler [mailto:sitsofe@xxxxxxxxx] Sent: Monday, August 21, 2017 3:16 PM To: Mikhail Terekhov <Mikhail.Terekhov@xxxxxxxx> Cc: Jeff Furlong <jeff.furlong@xxxxxxx>; Gruher, Joseph R <joseph.r.gruher@xxxxxxxxx>; neto from Brazil <Antonio.Jose.Rodrigues.Neto@xxxxxxxxxx>; fio@xxxxxxxxxxxxxxx Subject: Re: IOPS Log Incorrect? Joseph, Does the suggested fix solve the problem you were seeing too? On 21 August 2017 at 23:10, Mikhail Terekhov <Mikhail.Terekhov@xxxxxxxx> wrote:It seems fixed the problem. Here the results for fio-2.99 and fio-2.99+patch for rotating media: :/tmp>cat test299_iops.1.log 5000, 1448, 0, 0 10641, 180, 0, 0 15576, 160, 0, 0 20511, 204, 0, 0 25446, 222, 0, 0 30381, 126, 0, 0 :/tmp>cat test299p1_iops.1.log 5000, 1746, 0, 0 10000, 1435, 0, 0 15000, 1478, 0, 0 20000, 1161, 0, 0 25000, 1291, 0, 0 30000, 1265, 0, 0 On 08/21/17 17:12, Sitsofe Wheeler wrote:Hmm. How do things look with the following? diff --git a/time.c b/time.c index edfe779..5e38aad 100644 --- a/time.c +++ b/time.c @@ -8,7 +8,7 @@ static unsigned long ns_granularity; void timespec_add_msec(struct timespec *ts, unsigned int msec) { - unsigned long adj_nsec = 1000000 * msec; + unsigned long adj_nsec = 1000000UL * msec; ts->tv_nsec += adj_nsec; if (adj_nsec >= 1000000000) { Perhaps because msec is an unsigned int and 1000000 fits in an unsigned int the multiplication will wrap unexpectedly even though the real answer fits in a (64 bit) unsigned long? Perhaps adj_nsec needs to be a uint64_t ? On 21 August 2017 at 20:33, Jeff Furlong <jeff.furlong@xxxxxxx> wrote: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 in3.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 ofjoseph.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, soone 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=36lat (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-- Sitsofe | http://sucs.org/~sits/N�����r��y���b�X��ǧv�^�){.n�+���������ܨ}���Ơz�&j:+v�������zZ+��+zf���h���~����i���z� �w���?����&�)ߢfl===
-- 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
