Hi there,
I'm trying to understand difference in latency reported by fdatasync latency percentiles (_sync percentiles_) on `--ioengine=psync --fdatasync=1` vs. _clat percentiles_ on `--ioengine=libaio --direct=1` and I'd really appreciate your help.
I thought that they should should not have such a big difference between each other. I've assumed (am I wrong here?) that fdatasync latency percentiles (_sync percentiles_) will report on I/O completion for `fdatasync()` syscall, so that I could compare it with _clat percentiles_ on `--ioengine=libaio --direct=1`.
Can someone please help to explain how fdatasync latency percentiles (_sync percentiles_) on `--ioengine=psync --fdatasync=1` are calculated exactly?
My goal is to reproduce application pattern where for each of its `pwrite64()` calls it executes `fdatasync()` + I want to measure `fdatasync()` completion latency.
Test A:
$ sudo fio --rw=write --ioengine=psync --fdatasync=1 --iodepth=1 --bs=512 --numjobs=1 --rate_iops=1 --directory=test-data --size=100mb --runtime=1m --name=azure-westeurope-disk-test
azure-westeurope-disk-test: (g=0): rw=write, bs=(R) 512B-512B, (W) 512B-512B, (T) 512B-512B, ioengine=psync, iodepth=1
fio-3.7
Starting 1 process
azure-westeurope-disk-test: Laying out IO file (1 file / 100MiB)
Jobs: 1 (f=1), 0-1 IOPS: [W(1)][100.0%][r=0KiB/s,w=0KiB/s][r=0,w=1 IOPS][eta 00m:00s]
azure-westeurope-disk-test: (groupid=0, jobs=1): err= 0: pid=12184: Tue Jul 12 18:35:15 2022
write: IOPS=1, BW=520B/s (520B/s)(30.5KiB/60001msec)
clat (nsec): min=9400, max=44200, avg=29336.07, stdev=6777.19
lat (nsec): min=10300, max=48300, avg=31836.07, stdev=7118.83
clat percentiles (nsec):
| 1.00th=[ 9408], 5.00th=[15808], 10.00th=[25728], 20.00th=[26496],
| 30.00th=[27008], 40.00th=[27776], 50.00th=[28288], 60.00th=[29312],
| 70.00th=[32640], 80.00th=[33536], 90.00th=[35584], 95.00th=[42240],
| 99.00th=[44288], 99.50th=[44288], 99.90th=[44288], 99.95th=[44288],
| 99.99th=[44288]
bw ( KiB/s): min= 0, max= 2, per=100.00%, avg= 1.00, stdev= 0.19, samples=59
iops : min= 1, max= 4, avg= 2.02, stdev= 0.29, samples=59
lat (usec) : 10=1.64%, 20=6.56%, 50=91.80%
fsync/fdatasync/sync_file_range:
sync (usec): min=1112, max=8494, avg=1999.62, stdev=1242.89
sync percentiles (usec):
| 1.00th=[ 1106], 5.00th=[ 1172], 10.00th=[ 1205], 20.00th=[ 1287],
| 30.00th=[ 1369], 40.00th=[ 1434], 50.00th=[ 1516], 60.00th=[ 1631],
| 70.00th=[ 1860], 80.00th=[ 2507], 90.00th=[ 3326], 95.00th=[ 4293],
| 99.00th=[ 8455], 99.50th=[ 8455], 99.90th=[ 8455], 99.95th=[ 8455],
| 99.99th=[ 8455]
cpu : usr=0.01%, sys=0.01%, ctx=136, majf=0, minf=34
IO depths : 1=198.4%, 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,61,0,0 short=60,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=520B/s (520B/s), 520B/s-520B/s (520B/s-520B/s), io=30.5KiB (31.2kB), run=60001-60001msec
Disk stats (read/write):
sdb: ios=0/282, merge=0/22, ticks=0/482, in_queue=482, util=0.56%
Test B:
$ sudo fio --rw=write --ioengine=libaio --direct=1 --iodepth=1 --bs=512 --numjobs=1 --rate_iops=1 --directory=test-data --size=100mb --runtime=1m --name=azure-westeurope-disk-test
azure-westeurope-disk-test: (g=0): rw=write, bs=(R) 512B-512B, (W) 512B-512B, (T) 512B-512B, ioengine=libaio, iodepth=1
fio-3.7
Starting 1 process
Jobs: 1 (f=1), 0-1 IOPS: [W(1)][100.0%][r=0KiB/s,w=0KiB/s][r=0,w=1 IOPS][eta 00m:00s]
azure-westeurope-disk-test: (groupid=0, jobs=1): err= 0: pid=12291: Tue Jul 12 18:36:35 2022
write: IOPS=1, BW=520B/s (520B/s)(30.5KiB/60002msec)
slat (usec): min=1140, max=4786, avg=1654.72, stdev=693.43
clat (nsec): min=3300, max=12200, avg=5070.49, stdev=1429.96
lat (usec): min=1148, max=4794, avg=1662.44, stdev=693.39
clat percentiles (nsec):
| 1.00th=[ 3312], 5.00th=[ 4320], 10.00th=[ 4320], 20.00th=[ 4384],
| 30.00th=[ 4576], 40.00th=[ 4704], 50.00th=[ 4704], 60.00th=[ 4832],
| 70.00th=[ 4832], 80.00th=[ 5088], 90.00th=[ 5472], 95.00th=[ 9152],
| 99.00th=[12224], 99.50th=[12224], 99.90th=[12224], 99.95th=[12224],
| 99.99th=[12224]
bw ( KiB/s): min= 0, max= 2, per=100.00%, avg= 1.00, stdev= 0.19, samples=59
iops : min= 1, max= 4, avg= 2.02, stdev= 0.29, samples=59
lat (usec) : 4=1.64%, 10=96.72%, 20=1.64%
cpu : usr=0.00%, sys=0.01%, ctx=122, majf=0, minf=32
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,61,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=520B/s (520B/s), 520B/s-520B/s (520B/s-520B/s), io=30.5KiB (31.2kB), run=60002-60002msec
Disk stats (read/write):
sdb: ios=0/301, merge=0/18, ticks=0/432, in_queue=432, util=0.62%
Thanks a lot in advance!
Alex
