From 119b7ce8e53226aa889cc243c08ec4892a5ec63b Mon Sep 17 00:00:00 2001 From: Vincent Fu Date: Mon, 12 Feb 2024 12:13:01 -0500 Subject: [PATCH] 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 --- HOWTO.rst | 15 +++++++++------ fio.1 | 14 ++++++++------ 2 files changed, 17 insertions(+), 12 deletions(-) diff --git a/HOWTO.rst b/HOWTO.rst index 53b03021..e5a5be03 100644 --- a/HOWTO.rst +++ b/HOWTO.rst @@ -4066,12 +4066,15 @@ Measurements and reporting .. 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 diff --git a/fio.1 b/fio.1 index 227fcb47..d832dba2 100644 --- a/fio.1 +++ b/fio.1 @@ -3765,12 +3765,14 @@ resulting in more precise time-related I/O statistics. 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 -- 2.25.1