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>
.. option:: log_avg_msec=int
- By default, fio will log an entry in the iops, latency, or bw log for every
- I/O that completes. When writing to the disk log, that can quickly grow to a
- very large size. Setting this option makes fio average the each log entry
- over the specified period of time, reducing the resolution of the log. See
- :option:`log_window_value` as well. Defaults to 0, logging all entries.
- Also see `Log File Formats`_.
+ By default, fio will log an entry in the iops, latency, or bw log for
+ every I/O that completes. When writing to the disk log, that can
+ quickly grow to a very large size. Setting this option directs fio to
+ instead record an average over the specified duration for each log
+ entry, reducing the resolution of the log. When the job completes, fio
+ will flush any accumulated latency log data, so the final log interval
+ may not match the value specified by this option and there may even be
+ duplicate timestamps. See :option:`log_window_value` as well. Defaults
+ to 0, logging entries for each I/O. Also see `Log File Formats`_.
.. option:: log_hist_msec=int
Also see \fBlog_avg_msec\fR as well. Defaults to 1024.
.TP
.BI log_avg_msec \fR=\fPint
-By default, fio will log an entry in the iops, latency, or bw log for every
-I/O that completes. When writing to the disk log, that can quickly grow to a
-very large size. Setting this option makes fio average the each log entry
-over the specified period of time, reducing the resolution of the log. See
-\fBlog_window_value\fR as well. Defaults to 0, logging all entries.
-Also see \fBLOG FILE FORMATS\fR section.
+By default, fio will log an entry in the iops, latency, or bw log for every I/O
+that completes. When writing to the disk log, that can quickly grow to a very
+large size. Setting this option directs fio to instead record an average over
+the specified duration for each log entry, reducing the resolution of the log.
+When the job completes, fio will flush any accumulated latency log data, so the
+final log interval may not match the value specified by this option and there
+may even be duplicate timestamps. See \fBlog_window_value\fR as well. Defaults
+to 0, logging entries for each I/O. Also see \fBLOG FILE FORMATS\fR section.
.TP
.BI log_hist_msec \fR=\fPint
Same as \fBlog_avg_msec\fR, but logs entries for completion latency
projects / fio.git / commitdiff