docs: explain duplicate logging timestamps
authorVincent Fu <vincent.fu@samsung.com>
Mon, 12 Feb 2024 17:13:01 +0000 (12:13 -0500)
committerVincent Fu <vincent.fu@samsung.com>
Tue, 13 Feb 2024 16:44:43 +0000 (11:44 -0500)
commit119b7ce8e53226aa889cc243c08ec4892a5ec63b
tree629f86919702e765bf8218b619b9097de9405670
parentba03f5afa7cd13a428305298a234db959d3f0c82
docs: explain duplicate logging timestamps

When a fio job ends, it cleans up by flushing any accumulated latency log
data for jobs with log_avg_msec enabled. This means that the final logging
interval may be different from what was specified by log_avg_msec. In
some cases there may even be duplicate timestamps. Add an explanation
for this phenomenon to the documentation.

During job cleanup it's possible to simply suppress the final log entry
if log_avg_msec has not passed since the previous log entry was recorded
but this throws away data that some users may depend on. For instance, a
55s job with log_avg_msec=10000 would have no long entry for the final
5s if we suppressed the final log entry.

Users concerned about final log entries with duplicate timestamps should
just ignore the second entry since it is likely based on only a handful
of I/Os.

Duplicate log entry example:

$ sudo ./fio --name=test --iodepth=2 --ioengine=libaio --time_based --runtime=5s --log_avg_msec=1000 --write_lat_log=test --filename=/dev/vda --direct=1
test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=2
fio-3.36-61-g9cfa-dirty
Starting 1 process
Jobs: 1 (f=1): [R(1)][100.0%][r=250MiB/s][r=64.0k IOPS][eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=1490: Mon Feb 12 12:19:13 2024
  read: IOPS=63.6k, BW=248MiB/s (260MB/s)(1242MiB/5001msec)
    slat (nsec): min=691, max=37070, avg=1272.54, stdev=674.26
    clat (usec): min=4, max=1731, avg=29.83, stdev= 7.03
     lat (usec): min=15, max=1734, avg=31.10, stdev= 7.19
    clat percentiles (usec):
     |  1.00th=[   23],  5.00th=[   25], 10.00th=[   26], 20.00th=[   27],
     | 30.00th=[   28], 40.00th=[   29], 50.00th=[   30], 60.00th=[   31],
     | 70.00th=[   32], 80.00th=[   33], 90.00th=[   35], 95.00th=[   37],
     | 99.00th=[   41], 99.50th=[   43], 99.90th=[   58], 99.95th=[   74],
     | 99.99th=[  104]
   bw (  KiB/s): min=244464, max=258112, per=100.00%, avg=254410.67, stdev=4788.90, samples=9
   iops        : min=61116, max=64528, avg=63602.67, stdev=1197.23, samples=9
  lat (usec)   : 10=0.01%, 20=0.06%, 50=99.76%, 100=0.16%, 250=0.01%
  lat (usec)   : 500=0.01%, 750=0.01%, 1000=0.01%
  lat (msec)   : 2=0.01%
  cpu          : usr=11.46%, sys=18.20%, ctx=159414, majf=0, minf=49
  IO depths    : 1=0.1%, 2=100.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.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.0%
     issued rwts: total=317842,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=2

Run status group 0 (all jobs):
   READ: bw=248MiB/s (260MB/s), 248MiB/s-248MiB/s (260MB/s-260MB/s), io=1242MiB (1302MB), run=5001-5001msec

Disk stats (read/write):
  vda: ios=311248/0, sectors=2489984/0, merge=0/0, ticks=7615/0, in_queue=7615, util=98.10%
$ cat test_lat.1.log
1000, 31907, 0, 0, 0
2000, 30705, 0, 0, 0
3000, 30738, 0, 0, 0
4000, 31196, 0, 0, 0
5000, 30997, 0, 0, 0
5000, 31559, 0, 0, 0

Signed-off-by: Vincent Fu <vincent.fu@samsung.com>
HOWTO.rst
fio.1