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 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
--
Sitsofe | http://sucs.org/~sits/
--
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
