**Avg latency: 1967 usec & Throughput: 6268 MiB/s**

[raj-prince]

Avg latency: 1967 usec & Throughput: 6268 MiB/s

Workload: (groupid=0, jobs=50): err= 0: pid=331555: Mon Jan 22 18:35:35 2024
  read: IOPS=12.5k, BW=6268MiB/s (6572MB/s)(488GiB/79775msec)
    slat (usec): min=18, max=5507, avg=46.77, stdev=14.14
    clat (usec): min=315, max=118161, avg=1920.54, stdev=4726.01
     lat (usec): min=341, max=118207, avg=1967.31, stdev=4725.74
    clat percentiles (usec):
     |  1.00th=[  445],  5.00th=[  490], 10.00th=[  523], 20.00th=[  578],
     | 30.00th=[  627], 40.00th=[  685], 50.00th=[  758], 60.00th=[  865],
     | 70.00th=[ 1004], 80.00th=[ 1270], 90.00th=[ 2671], 95.00th=[ 8029],
     | 99.00th=[25035], 99.50th=[33424], 99.90th=[54789], 99.95th=[62653],
     | 99.99th=[80217]
   bw (  MiB/s): min= 3481, max=14820, per=100.00%, avg=6568.71, stdev=29.51, samples=7532
   iops        : min= 6956, max=29635, avg=13133.76, stdev=59.01, samples=7532
  lat (usec)   : 500=6.47%, 750=42.09%, 1000=21.16%
  lat (msec)   : 2=18.17%, 4=4.12%, 10=3.87%, 20=2.64%, 50=1.33%
  lat (msec)   : 100=0.14%, 250=0.01%
  cpu          : usr=47.96%, sys=1.62%, ctx=1042689, majf=138, minf=87426
  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=1000000,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=64

Run status group 0 (all jobs):
   READ: bw=6268MiB/s (6572MB/s), 6268MiB/s-6268MiB/s (6572MB/s-6572MB/s), io=488GiB (524GB), run=79775-79775msec

Avg latency: 2249 usec & Throughput: 3039 MiB/s

Workload: (groupid=0, jobs=50): err= 0: pid=330152: Mon Jan 22 18:14:44 2024
  read: IOPS=6077, BW=3039MiB/s (3186MB/s)(488GiB/164548msec)
    slat (usec): min=898, max=92979, avg=2241.49, stdev=1359.10
    clat (nsec): min=1606, max=12033k, avg=8210.54, stdev=22231.77
     lat (usec): min=902, max=92990, avg=2249.70, stdev=1359.62
    clat percentiles (usec):
     |  1.00th=[    4],  5.00th=[    5], 10.00th=[    5], 20.00th=[    6],
     | 30.00th=[    6], 40.00th=[    7], 50.00th=[    7], 60.00th=[    8],
     | 70.00th=[    8], 80.00th=[    9], 90.00th=[   11], 95.00th=[   14],
     | 99.00th=[   30], 99.50th=[   46], 99.90th=[  149], 99.95th=[  247],
     | 99.99th=[  734]
   bw (  MiB/s): min=  687, max= 5668, per=100.00%, avg=3076.70, stdev=12.47, samples=16195
   iops        : min= 1360, max=11328, avg=6146.57, stdev=24.91, samples=16195
  lat (usec)   : 2=0.01%, 4=1.66%, 10=86.54%, 20=9.61%, 50=1.75%
  lat (usec)   : 100=0.28%, 250=0.11%, 500=0.03%, 750=0.01%, 1000=0.01%
  lat (msec)   : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%
  cpu          : usr=41.37%, sys=1.12%, ctx=6071028, majf=153, minf=268353
  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=1000000,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=64

Run status group 0 (all jobs):
   READ: bw=3039MiB/s (3186MB/s), 3039MiB/s-3039MiB/s (3186MB/s-3186MB/s), io=488GiB (524GB), run=164548-164548msec

As we can see clearly, average latency differs only by 300 usec but throughput is almost 2x.

1. Could you please some one help in understanding - what would be the root cause?
2. Does the read latency also includes the time in StatFile, OpenFile, and CloseFile?

Originally posted by @raj-prince in https://github.com/axboe/fio/discussions/1704