From: Vincent Fu <Vincent.Fu@sandisk.com>
Date: Thu, 16 Mar 2017 16:11:46 +0000 (-0400)
Subject: nanosecond: update completion latency recording and normal, json output to use nanose... 
X-Git-Tag: fio-2.99~72^2~1^2~10
X-Git-Url: https://git.kernel.dk/?p=fio.git;a=commitdiff_plain;h=d6bb626ef37d3905221ade2887b422717a07af09;hp=d6bb626ef37d3905221ade2887b422717a07af09;ds=sidebyside

nanosecond: update completion latency recording and normal, json output to use nanoseconds

A new set of nsec bins (0-1, 2-3, 4-9, 10-19, ...) is created for tracking latencies.
The number of io_u_plat[] latency bins is increased by about 50% to accommodate the
greater resolution while retaining the same max latency value of ~9 seconds.

Example output

test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=null, iodepth=1
fio-2.20-39-g83b3
Starting 1 process
Jobs: 1 (f=1): [R(1)][100.0%][r=14.6GiB/s,w=0KiB/s][r=3832k,w=0 IOPS][eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=17621: Thu Jun  1 15:09:38 2017
   read: IOPS=3784k, BW=14.4GiB/s (15.5GB/s)(144GiB/10000msec)
    clat (nsec): min=15, max=1685.2k, avg=26.92, stdev=433.62
     lat (nsec): min=46, max=5989.9k, avg=67.31, stdev=1659.58
    clat percentiles (nsec):
     |  1.00th=[   18],  5.00th=[   18], 10.00th=[   19], 20.00th=[   19],
     | 30.00th=[   22], 40.00th=[   22], 50.00th=[   25], 60.00th=[   26],
     | 70.00th=[   26], 80.00th=[   27], 90.00th=[   36], 95.00th=[   41],
     | 99.00th=[   46], 99.50th=[   50], 99.90th=[  104], 99.95th=[  139],
     | 99.99th=[ 7840]
   bw (  MiB/s): min=13393, max=15647, per=0.10%, avg=14784.86, stdev=558.40
    lat (nsec) : 20=20.87%, 50=78.57%, 100=0.43%, 250=0.10%, 500=0.01%
    lat (nsec) : 750=0.01%, 1000=0.01%
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 1000=0.01%
    lat (msec) : 2=0.01%
  cpu          : usr=99.72%, sys=0.12%, ctx=321, majf=0, minf=8
  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=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=37840231,0,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: bw=14.4GiB/s (15.5GB/s), 14.4GiB/s-14.4GiB/s (15.5GB/s-15.5GB/s), io=144GiB (155GB), run=10000-10000msec
---