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>