Skip to content

backend: initialize comp_time before the rate checks read it - #2130

Open
Vladyyy wants to merge 1 commit into
axboe:masterfrom
Vladyyy:do-io-init-comp-time
Open

backend: initialize comp_time before the rate checks read it#2130
Vladyyy wants to merge 1 commit into
axboe:masterfrom
Vladyyy:do-io-init-comp-time

Conversation

@Vladyyy

@Vladyyy Vladyyy commented Aug 6, 2026

Copy link
Copy Markdown

do_io() declared comp_time uninitialized inside the IO loop. It is
only stamped by wait_for_completions() (called when the queue is full
or when polling) and by io_queue_event()'s inline-completion path. An
async engine on a block device with a rate limit takes neither:
submissions return FIO_Q_QUEUED and completions are reaped during the
rate-throttle sleep via io_u_quiesce(), which does not touch
comp_time. Once bytes_done is non-zero, check_min_rate() (enabled by
rate_iops_min / ratemin) computes mtime_since(&td->start, &comp_time)
from whatever bytes happen to be on the stack, and when the garbage
tv_nsec is out of range rel_time_since() aborts:

fio: gettime.c:530: rel_time_since: Assertion `0 <= nsec && nsec < 1000ULL * 1000 * 1000' failed.

This crashed every run of a rate-limited randwrite latency workload
(libaio, iodepth=16, rate_iops=500, rate_iops_min=500, write_lat_log)
~100 ms after start on our EC2 test fleet, deterministically per host:
the stack leftovers at that slot depend on the preceding code paths,
so the same binary can crash on one fleet and run clean on another.
When the garbage is numerically benign there is no crash, but the
min-rate settle arithmetic is still computed from garbage.

Hoist comp_time to function scope and seed it with fio_gettime() at
do_io() entry (the previous declaration was loop-scoped, so it was
fresh garbage on every iteration). A seed at loop start is safe: until
the first real completion stamp the settle check just stays inside its
2-second settle window, which is the intended behavior for the start
of a job anyway. handle_thinktime() only ever writes the passed time,
so check_min_rate() is the sole reader.

Tested with the workload above against a loop device: runs complete
cleanly with correct sample counts (5000 lat samples for a 10s run at
500 IOPS), and seeding comp_time with the exact garbage values
recovered from a production core dump no longer has any code path to
reach the rate checks.

Fixes: #2128

Signed-off-by: Vlad Tudose tudosevt@amazon.com

do_io() declared comp_time uninitialized inside the IO loop. It is
only stamped by wait_for_completions() (called when the queue is full
or when polling) and by io_queue_event()'s inline-completion path. An
async engine on a block device with a rate limit takes neither:
submissions return FIO_Q_QUEUED and completions are reaped during the
rate-throttle sleep via io_u_quiesce(), which does not touch
comp_time. Once bytes_done is non-zero, check_min_rate() (enabled by
rate_iops_min / ratemin) computes mtime_since(&td->start, &comp_time)
from whatever bytes happen to be on the stack, and when the garbage
tv_nsec is out of range rel_time_since() aborts:

  fio: gettime.c:530: rel_time_since: Assertion `0 <= nsec && nsec < 1000ULL * 1000 * 1000' failed.

This crashed every run of a rate-limited randwrite latency workload
(libaio, iodepth=16, rate_iops=500, rate_iops_min=500, write_lat_log)
~100 ms after start on our EC2 test fleet, deterministically per host:
the stack leftovers at that slot depend on the preceding code paths,
so the same binary can crash on one fleet and run clean on another.
When the garbage is numerically benign there is no crash, but the
min-rate settle arithmetic is still computed from garbage.

Hoist comp_time to function scope and seed it with fio_gettime() at
do_io() entry (the previous declaration was loop-scoped, so it was
fresh garbage on every iteration). A seed at loop start is safe: until
the first real completion stamp the settle check just stays inside its
2-second settle window, which is the intended behavior for the start
of a job anyway. handle_thinktime() only ever writes the passed time,
so check_min_rate() is the sole reader.

Tested with the workload above against a loop device: runs complete
cleanly with correct sample counts (5000 lat samples for a 10s run at
500 IOPS), and seeding comp_time with the exact garbage values
recovered from a production core dump no longer has any code path to
reach the rate checks.

Fixes: axboe#2128

Signed-off-by: Vlad Tudose <tudosevt@amazon.com>
@Vladyyy
Vladyyy force-pushed the do-io-init-comp-time branch from 3f2b727 to 3566475 Compare August 6, 2026 23:47
@vincentkfu

Copy link
Copy Markdown
Collaborator

The patch does prevent the assert but comp_time seems to never be stamped with this workload so rate_min is never enforced and falling below the specified threshold will never be detected.

If I comment out the abort in init.c:fixup_options() when rate_iops < rate_min with this patch I can run this job that sets rate_iops=500 rate_iops_min=1000:

root@localhost:~/fio-dev/fio-canonical# ./fio --name=test --ioengine=libaio --iodepth=16 --filename=/dev/nvme0n1 --rate_iops=500 --time_based --runtime=5s --rate_iops_min=1000
fio: minimum rate exceeds rate, ddir 0
fio: minimum rate exceeds rate, ddir 1
fio: minimum rate exceeds rate, ddir 2
test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
fio-3.42-120-g3cc7-dirty
Starting 1 process
Jobs: 1 (f=1), 1000-500 IOPS: [R(1)][100.0%][r=2000KiB/s][r=500 IOPS][eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=48941: Tue Aug 11 20:06:36 2026
  read: IOPS=499, BW=2000KiB/s (2048kB/s)(9.77MiB/5001msec)
    slat (usec): min=5, max=809, avg=19.91, stdev=40.17
    clat (nsec): min=2867, max=23705, avg=6546.85, stdev=2090.69
     lat (usec): min=8, max=817, avg=26.46, stdev=40.87
    clat percentiles (nsec):
     |  1.00th=[ 3600],  5.00th=[ 3984], 10.00th=[ 4448], 20.00th=[ 4576],
     | 30.00th=[ 4704], 40.00th=[ 4960], 50.00th=[ 7008], 60.00th=[ 7328],
     | 70.00th=[ 8384], 80.00th=[ 8640], 90.00th=[ 8896], 95.00th=[ 9024],
     | 99.00th=[10176], 99.50th=[13760], 99.90th=[22144], 99.95th=[23168],
     | 99.99th=[23680]
   bw (  KiB/s): min= 1968, max= 2008, per=99.97%, avg=1999.50, stdev=11.65, samples=10
   iops        : min=  492, max=  502, avg=499.80, stdev= 2.90, samples=10
  lat (usec)   : 4=5.00%, 10=93.92%, 20=0.84%, 50=0.24%
  cpu          : usr=3.38%, sys=0.00%, ctx=2501, majf=0, minf=9
  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=2500,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0.00ns, window=0.00ns, percentile=100.00%, depth=16

Run status group 0 (all jobs):
   READ: bw=2000KiB/s (2048kB/s), 2000KiB/s-2000KiB/s (2048kB/s-2048kB/s), io=9.77MiB (10.2MB), run=5001-5001msec

Disk stats (read/write):
  nvme0n1: ios=47/0, sectors=20480/0, merge=0/0, ticks=24/0, in_queue=24, util=0.00%

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

do_io: uninitialized comp_time can reach check_min_rate (assert in rel_time_since / SIGABRT)

2 participants