Why we see difference in throughput although the average latency is not differing much?

[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?

[vincentkfu]

It is difficult to provide feedback without the full job file(s) used to produce the output above.

[vincentkfu]

In general latency is the difference between the start time for an io_u and its completion time. IOPS and bandwidth are (total number of bytes or operataions) / (total time for the job). There are some activities that fio carries out that are not captured in the latency of an IO. It's also possible that iodepth can affect the relationship between latency and BW (although both your jobs seem to be QD 1). Without more details about your jobs there is no way to provide an answer.

[raj-prince]

Thanks @vincentkfu to look into this !

; -- use nrfiles and rw to CLI args to control readtype and number of files --
[global]
ioengine=libaio
direct=1
fadvise_hint=0
iodepth=64
invalidate=1
nrfiles=20000
thread=1
openfiles=1
group_reporting=1
create_serialize=0
allrandrepeat=0
file_service_type=random
numjobs=50
filename_format=$jobname.$jobnum/$filenum

[Workload]
directory=${DIR}
bs=512K
filesize=512K
rw=read

The above two outputs are generated by the same fio spec pasted above. The only difference is workload directory - one is SSD and one is gcsfuse mounted directory (fuse based system).

To differentiate further b/w both the workload dirctory:

• Generally, we see four calls to read a file via FIO: (a) StatFile (b) OpenFile (c) ReadFile (d) CloseFile
• In case of gcsfuse-mounted directory the latency of StatFile, OpenFile latency is significant. That's why I wanted to ask this question; does the fio latency include all these non-ReadFile latency?

[raj-prince]

@vincentkfu gentle reminder, as getting root cause is very important for us!

To add more context:
We are using the same job file on two different file-system - (i) 3039 MiB/s is the throughput while reading via gcsfuse mounted directory (ii) Other one is with local-SSD.

Also, one more observation:
For 3039 MiB/s: slat is higher, clat is almost 0.
For 6268 MiB/s: slat is almost 0, and clat is higher.
Do you know the reasoning behind this?

[vincentkfu]

io_u.c:get_io_u() has the information you are looking for:

struct io_u *get_io_u(struct thread_data *td)
{
...
	/*
	 * If using an iolog, grab next piece if any available.
	 */
	if (td->flags & TD_F_READ_IOLOG) {
		if (read_iolog_get(td, io_u))
			goto err_put;
	} else if (set_io_u_file(td, io_u)) {
		ret = -EBUSY;
		dprint(FD_IO, "io_u %p, setting file failed\n", io_u);
		goto err_put;
	}

	f = io_u->file;
	if (!f) {
		dprint(FD_IO, "io_u %p, setting file failed\n", io_u);
		goto err_put;
	}

...

out:
	assert(io_u->file);
	if (!td_io_prep(td, io_u)) {
		if (!td->o.disable_lat)
			fio_gettime(&io_u->start_time, NULL);

		if (do_scramble)
			small_content_scramble(io_u);

		return io_u;
	}

The first quoted block contains a call to set_io_u_file() where a file is assigned to this io_u (or IO unit). The file is also opened when it is assigned to the io_u. Then later on in the second quoted block, io_u->start_time is set. From this we can deduce that the time required to open a file is not counted in an IO's latency. Since your job has openfiles=1 a new file is opened essentially every time an IO is issued.

So I think we have an explanation for the discrepancy between latency and bandwidth. The latency values are similar but bandwidth differs because time required to open a file is not included in the latency measurement.

For more details about latency measurement see: https://github.com/vincentkfu/fio-blog/wiki/How-does-fio-measure-latency

[raj-prince]

Thanks @vincentkfu for the clarification!

One more doubt I have - for fio output having throughput 3039 MiB/s, the average cLat is 8210.54 us, which doesn't seem reasonable to me. Also sLat is higher for this output, ideally it shouldn't be that much. As sLat is the time taken to create the IO to the submit the IO in the io_engine's queue.

Do you have any idea, why it's happening?

[vincentkfu]

The clat/slat discrepancy between the two file systems is unlikely to be related to fio. Consider using perf (as suggested at #963) to compare the two runs.

[raj-prince]

Increasing the number of open_files in fio job solved the clat/slat discrepancy.

I would like to confirm one thing - here - as we can see while opening the file, we add the latency as cLat. Does this flow work for libaio? Or am l looking at the wrong place?

[vincentkfu]

The file operation ioengines work differently from all the other ioengines. They use the data structure other ioengines use for IO latency to record latencies for file open operations. libaio does not work this way.

Most ioengines call add_clat_sample in io_u.c:account_io_completion

[raj-prince]

Got it, generic_file_open is called in that case.

[raj-prince]

Also, do we hit any edge case in the calculation of sLat and cLat? when
(a) OpenFile takes significant time.
(b) No. of open_files = 1

Let's take a scenario for one Job:
(a) There is an ongoing operation in the libaio (kernel queue), submitted via io_submit system call.
(b) We would be preparing for the next file.
(c) So, there might be chance, for the next file we initialize the issue_time and not able to submit in the (libaio) system because of open_file constraint. And due to that, we can see a large sLat irrespective of open file call doesn't contribute to sLat.

[vincentkfu]

The options below put fio in a difficult position:

ioengine=libaio
iodepth=64
nrfiles=20000
openfiles=1
file_service_type=random

Fio is instructed to maintain an iodepth of 64 yet openfiles is limited to 1 and file_service_type is set to random. These options cannot be simultaneously all satisfied. I haven't checked the code, but what fio seems to be doing is choosing "randomly" from the set of open files which results in fio operating on one file at a time.

Run small versions of jobs you are interested in with --debug=io,file. The debug output below suggests fio does open one file at a time and the latency measurements are all taken outside of the file open operations. So there should be no impact of slow openfile operations on latency measurements.

vincent@fio-dev:~/fio-dev/fio-canonical$ ./fio --name=test --ioengine=libaio --direct=1 --filesize=16k --rw=randread --iodepth=4 --nrfiles=4 --openfiles=1 --debug=io,file
fio: set debug option io
fio: set debug option file
file     5346  add file test.0.0
file     5346  resize file array to 5 files
file     5346  file 0x7fe1167c1110 "test.0.0" added at 0
file     5346  add file test.0.1
file     5346  file 0x7fe1167c12d0 "test.0.1" added at 1
file     5346  add file test.0.2
file     5346  file 0x7fe1167c1490 "test.0.2" added at 2
file     5346  add file test.0.3
file     5346  file 0x7fe1167c1650 "test.0.3" added at 3
test: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=4
fio-3.36-88-g9af4af
Starting 1 process
file     5346  setup files
file     5346  get file size for 0x7fe1167c1110/0/test.0.0
file     5346  get file size for 0x7fe1167c12d0/1/test.0.1
file     5346  get file size for 0x7fe1167c1490/2/test.0.2
file     5346  get file size for 0x7fe1167c1650/3/test.0.3
test: Laying out IO files (4 files / total 0MiB)
file     5346  layout unlink test.0.0
file     5346  open file test.0.0, flags 241
file     5346  native fallocate of file test.0.0 size 16384 was successful
file     5346  truncate file test.0.0, size 16384
io       5346  declare unneeded cache test.0.0: 0/16384
file     5346  layout unlink test.0.1
file     5346  open file test.0.1, flags 241
file     5346  native fallocate of file test.0.1 size 16384 was successful
file     5346  truncate file test.0.1, size 16384
io       5346  declare unneeded cache test.0.1: 0/16384
file     5346  layout unlink test.0.2
file     5346  open file test.0.2, flags 241
file     5346  native fallocate of file test.0.2 size 16384 was successful
file     5346  truncate file test.0.2, size 16384
io       5346  declare unneeded cache test.0.2: 0/16384
file     5346  layout unlink test.0.3
file     5346  open file test.0.3, flags 241
file     5346  native fallocate of file test.0.3 size 16384 was successful
file     5346  truncate file test.0.3, size 16384
io       5346  declare unneeded cache test.0.3: 0/16384
file     5348  trying file test.0.0 290
file     5348  fd open test.0.0
file     5348  file not found in hash test.0.0
file     5348  get file test.0.0, ref=0
io       5348  declare unneeded cache test.0.0: 0/16384
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1110
file     5348  get_next_file: 0x7fe1167c1110 [test.0.0]
file     5348  get file test.0.0, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.0
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.1 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.0
file     5348  put file test.0.0, ref=2
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1110
file     5348  get_next_file: 0x7fe1167c1110 [test.0.0]
file     5348  get file test.0.0, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.0
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.1 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.0
file     5348  put file test.0.0, ref=2
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1110
file     5348  get_next_file: 0x7fe1167c1110 [test.0.0]
file     5348  get file test.0.0, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.0
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.1 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.0
file     5348  put file test.0.0, ref=2
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1110
file     5348  get_next_file: 0x7fe1167c1110 [test.0.0]
file     5348  get file test.0.0, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.0
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.0
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.1 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.0
file     5348  put file test.0.0, ref=2
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1110
file     5348  get_next_file: 0x7fe1167c1110 [test.0.0]
file     5348  get file test.0.0, ref=1
io       5348  test.0.0: rand offset failed, last=8192, size=16384
io       5348  io_u 0x55a29843e700, failed getting offset
file     5348  put file test.0.0, ref=2
file     5348  put file test.0.0, ref=1
file     5348  fd close test.0.0
file     5348  test.0.0: is done (1 of 4)
file     5348  trying file test.0.1 290
file     5348  fd open test.0.1
file     5348  file not found in hash test.0.1
file     5348  get file test.0.1, ref=0
io       5348  declare unneeded cache test.0.1: 0/16384
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c12d0
file     5348  get_next_file: 0x7fe1167c12d0 [test.0.1]
file     5348  get file test.0.1, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.1
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.1
file     5348  put file test.0.1, ref=2
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c12d0
file     5348  get_next_file: 0x7fe1167c12d0 [test.0.1]
file     5348  get file test.0.1, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.1
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.1
file     5348  put file test.0.1, ref=2
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c12d0
file     5348  get_next_file: 0x7fe1167c12d0 [test.0.1]
file     5348  get file test.0.1, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.1
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.1
file     5348  put file test.0.1, ref=2
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c12d0
file     5348  get_next_file: 0x7fe1167c12d0 [test.0.1]
file     5348  get file test.0.1, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.1
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.1
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.2 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.1
file     5348  put file test.0.1, ref=2
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e700, setting file failed
io       5348  get_io_u failed
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c12d0
file     5348  get_next_file: 0x7fe1167c12d0 [test.0.1]
file     5348  get file test.0.1, ref=1
io       5348  test.0.1: rand offset failed, last=12288, size=16384
io       5348  io_u 0x55a29843e700, failed getting offset
file     5348  put file test.0.1, ref=2
file     5348  put file test.0.1, ref=1
file     5348  fd close test.0.1
file     5348  test.0.1: is done (2 of 4)
file     5348  trying file test.0.2 290
file     5348  fd open test.0.2
file     5348  file not found in hash test.0.2
file     5348  get file test.0.2, ref=0
io       5348  declare unneeded cache test.0.2: 0/16384
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1490
file     5348  get_next_file: 0x7fe1167c1490 [test.0.2]
file     5348  get file test.0.2, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.2
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.2
file     5348  put file test.0.2, ref=2
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1490
file     5348  get_next_file: 0x7fe1167c1490 [test.0.2]
file     5348  get file test.0.2, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.2
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x3000,len=0x1000,ddir=0,file=test.0.2
file     5348  put file test.0.2, ref=2
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1490
file     5348  get_next_file: 0x7fe1167c1490 [test.0.2]
file     5348  get file test.0.2, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.2
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x0,len=0x1000,ddir=0,file=test.0.2
file     5348  put file test.0.2, ref=2
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1490
file     5348  get_next_file: 0x7fe1167c1490 [test.0.2]
file     5348  get file test.0.2, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.2
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.2
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.3 290
io       5348  io_u 0x55a29843e1c0, setting file failed
io       5348  get_io_u failed
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x1000,len=0x1000,ddir=0,file=test.0.2
file     5348  put file test.0.2, ref=2
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1490
file     5348  get_next_file: 0x7fe1167c1490 [test.0.2]
file     5348  get file test.0.2, ref=1
io       5348  test.0.2: rand offset failed, last=8192, size=16384
io       5348  io_u 0x55a29843e700, failed getting offset
file     5348  put file test.0.2, ref=2
file     5348  put file test.0.2, ref=1
file     5348  fd close test.0.2
file     5348  test.0.2: is done (3 of 4)
file     5348  trying file test.0.3 290
file     5348  fd open test.0.3
file     5348  file not found in hash test.0.3
file     5348  get file test.0.3, ref=0
io       5348  declare unneeded cache test.0.3: 0/16384
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1650
file     5348  get_next_file: 0x7fe1167c1650 [test.0.3]
file     5348  get file test.0.3, ref=1
io       5348  fill: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e700: ret=0
io       5348  queue: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.3
io       5348  calling ->commit(), depth 1
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 298
file     5348  trying file test.0.3 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1650
file     5348  get_next_file: 0x7fe1167c1650 [test.0.3]
file     5348  get file test.0.3, ref=2
io       5348  fill: io_u 0x55a29843e1c0: off=0x3000,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e1c0: off=0x3000,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e1c0: ret=0
io       5348  queue: io_u 0x55a29843e1c0: off=0x3000,len=0x1000,ddir=0,file=test.0.3
io       5348  calling ->commit(), depth 2
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 298
file     5348  trying file test.0.3 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1650
file     5348  get_next_file: 0x7fe1167c1650 [test.0.3]
file     5348  get file test.0.3, ref=3
io       5348  fill: io_u 0x55a29843e540: off=0x1000,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e540: off=0x1000,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e540: ret=0
io       5348  queue: io_u 0x55a29843e540: off=0x1000,len=0x1000,ddir=0,file=test.0.3
io       5348  calling ->commit(), depth 3
file     5348  trying file test.0.0 298
file     5348  trying file test.0.1 298
file     5348  trying file test.0.2 298
file     5348  trying file test.0.3 2b1
file     5348  goodf=1, badf=2, ff=2b1
file     5348  get_next_file_rr: 0x7fe1167c1650
file     5348  get_next_file: 0x7fe1167c1650 [test.0.3]
file     5348  get file test.0.3, ref=4
io       5348  fill: io_u 0x55a29843e000: off=0x0,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e000: off=0x0,len=0x1000,ddir=0,file=test.0.3
io       5348  prep: io_u 0x55a29843e000: ret=0
io       5348  queue: io_u 0x55a29843e000: off=0x0,len=0x1000,ddir=0,file=test.0.3
io       5348  calling ->commit(), depth 4
io       5348  io_u_queued_complete: min=1
io       5348  getevents: 1
io       5348  complete: io_u 0x55a29843e700: off=0x2000,len=0x1000,ddir=0,file=test.0.3
file     5348  put file test.0.3, ref=5
io       5348  io_u_queued_complete: min=3
io       5348  getevents: 3
io       5348  complete: io_u 0x55a29843e1c0: off=0x3000,len=0x1000,ddir=0,file=test.0.3
file     5348  put file test.0.3, ref=4
io       5348  complete: io_u 0x55a29843e540: off=0x1000,len=0x1000,ddir=0,file=test.0.3
file     5348  put file test.0.3, ref=3
io       5348  complete: io_u 0x55a29843e000: off=0x0,len=0x1000,ddir=0,file=test.0.3
file     5348  put file test.0.3, ref=2
file     5348  close files
file     5348  put file test.0.3, ref=1
file     5348  fd close test.0.3
io       5348  close ioengine libaio
io       5348  free ioengine libaio

test: (groupid=0, jobs=1): err= 0: pid=5348: Tue Feb 27 14:12:36 2024
  read: IOPS=4000, BW=15.6MiB/s (16.4MB/s)(64.0KiB/4msec)
    slat (nsec): min=19527, max=54062, avg=30237.50, stdev=10577.44
    clat (usec): min=96, max=345, avg=156.07, stdev=79.52
     lat (usec): min=121, max=393, avg=186.30, stdev=82.33
    clat percentiles (usec):
     |  1.00th=[   97],  5.00th=[   97], 10.00th=[   97], 20.00th=[  106],
     | 30.00th=[  109], 40.00th=[  114], 50.00th=[  120], 60.00th=[  139],
     | 70.00th=[  147], 80.00th=[  163], 90.00th=[  326], 95.00th=[  347],
     | 99.00th=[  347], 99.50th=[  347], 99.90th=[  347], 99.95th=[  347],
     | 99.99th=[  347]
  lat (usec)   : 100=12.50%, 250=68.75%, 500=18.75%
  cpu          : usr=100.00%, sys=0.00%, ctx=13, majf=0, minf=27
  IO depths    : 1=81.2%, 2=12.5%, 4=6.2%, 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=16,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=4

Run status group 0 (all jobs):
   READ: bw=15.6MiB/s (16.4MB/s), 15.6MiB/s-15.6MiB/s (16.4MB/s-16.4MB/s), io=64.0KiB (65.5kB), run=4-4msec

Disk stats (read/write):
  vda: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%
io       5346  ioengine libblkio unregistered
io       5346  ioengine libpmem unregistered
io       5346  ioengine dev-dax unregistered
io       5346  ioengine http unregistered
io       5346  ioengine rbd unregistered
io       5346  ioengine rados unregistered
io       5346  ioengine rdma unregistered
io       5346  ioengine libaio unregistered
io       5346  ioengine io_uring unregistered
io       5346  ioengine io_uring_cmd unregistered
io       5346  ioengine sg unregistered
io       5346  ioengine mtd unregistered
io       5346  ioengine gfapi_async unregistered
io       5346  ioengine gfapi unregistered
io       5346  ioengine splice unregistered
io       5346  ioengine e4defrag unregistered
io       5346  ioengine falloc unregistered
io       5346  ioengine posixaio unregistered
io       5346  ioengine nfs unregistered
io       5346  ioengine exec unregistered
io       5346  ioengine filecreate unregistered
io       5346  ioengine filestat unregistered
io       5346  ioengine filedelete unregistered
io       5346  ioengine ftruncate unregistered
io       5346  ioengine net unregistered
io       5346  ioengine netsplice unregistered
io       5346  ioengine null unregistered
io       5346  ioengine sync unregistered
io       5346  ioengine psync unregistered
io       5346  ioengine vsync unregistered
io       5346  ioengine pvsync unregistered
io       5346  ioengine pvsync2 unregistered
io       5346  ioengine mmap unregistered
io       5346  ioengine cpuio unregistered