Latency difference between fio statistics and blktrace

[givemealung]

Description of the bug: Hi,

In my case, I tried to figure where the latency comes from using blktrace. Somehow I found Q2D(should be the stat from when IO submitted to block layer and completed) from blktrace is kindly different from clat from fio. Tested with both async I/O engine and sync I/O engine, and it's only reproduced with sync I/O engine. In sync I/O case, latency data from fio statistics and blktrace is:

disk1: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=sync, iodepth=1
fio-3.35
Starting 1 process

disk1: (groupid=0, jobs=1): err= 0: pid=13733: Sat Mar 16 12:00:58 2024
  write: IOPS=26.3k, BW=103MiB/s (108MB/s)(30.1GiB/300001msec); 0 zone resets
    clat (usec): min=32, max=2848, avg=36.64, stdev= 3.08
     lat (usec): min=32, max=2849, avg=36.76, stdev= 3.09
    clat percentiles (nsec):
     |  1.00th=[34048],  5.00th=[35072], 10.00th=[35584], 20.00th=[36096],
     | 30.00th=[36096], 40.00th=[36608], 50.00th=[36608], 60.00th=[36608],
     | 70.00th=[37120], 80.00th=[37120], 90.00th=[37632], 95.00th=[37632],
     | 99.00th=[38144], 99.50th=[38656], 99.90th=[42752], 99.95th=[45824],
     | 99.99th=[70144]
   bw (  KiB/s): min=102896, max=106408, per=100.00%, avg=105230.40, stdev=982.11, samples=600
   iops        : min=25724, max=26602, avg=26307.49, stdev=245.53, samples=600
  lat (usec)   : 50=99.97%, 100=0.02%, 250=0.01%, 500=0.01%, 750=0.01%
  lat (usec)   : 1000=0.01%
  lat (msec)   : 2=0.01%, 4=0.01%
  cpu          : usr=6.71%, sys=8.24%, ctx=7889325, majf=0, minf=7730
  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=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=0,7889321,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: bw=103MiB/s (108MB/s), 103MiB/s-103MiB/s (108MB/s-108MB/s), io=30.1GiB (32.3GB), run=300001-300001msec

Disk stats (read/write):
  sdc: ios=16/12682120, merge=0/0, ticks=6/422116, in_queue=40, util=98.88%

==================== All Devices ====================

            ALL           MIN           AVG           MAX           N
--------------- ------------- ------------- ------------- -----------

Q2Q               0.000034440   0.000038722   0.001990850     1549489
Q2G               0.000000430   0.000000522   0.000013170     1549490
G2I               0.000000430   0.000000509   0.000011880     1549490
I2D               0.000001790   0.000002018   0.000019360     1549490
D2C               0.000026830   0.000030641   0.001982710     1549489
Q2C               0.000029800   0.000033689   0.001985750     1549489

Environment: CentOS Linux release 7.9.2009 (AltArch) 4.18.0-193.28.1.el7.aarch64

fio version: 3.35

Reproduction steps Test with below config file.

[global]

# generic param
group_reporting=1

# OS param
direct=1
ioengine=sync

# test param
runtime=300
ramp_time=180
numjobs=1
iodepth=1
rw=randwrite
bs=4k

# special param
numa_cpu_nodes=1
write_lat_log=sdc_lat.log

# target
[disk1]
name=disk1
filename=/dev/sdc

Other I found the explantion of ambigious latency in sync I/O case, possibly relative to the issue?#1110

[vincentkfu]

Fio issued 7889321 write commands whereas blktrace is provided data on 1549489 operations. I think it's unreasonable to expect the latencies to agree.

[givemealung]

Fio issued 7889321 write commands whereas blktrace is provided data on 1549489 operations. I think it's unreasonable to expect the latencies to agree.

Sorry for omitting the reply.

The difference of write commands count is mainly caused by sampling from blktrace is merely 1minutes, whereas fio run for 5 minutes plus 3-minute ramp time. However, average IO's completion time(Q2C, 33689ns) is even less than 1th percentile of clat(34048ns), it should tell on the problem.