Re: IOPS Log Incorrect?

Mikhail Terekhov <Mikhail.Terekhov@xxxxxxxx> · Mon, 21 Aug 2017 18:10:28 -0400

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 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



--
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






