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

[Vladyyy]

Please acknowledge the following before creating a ticket

• I have read the GitHub issues section of REPORTING-BUGS.

Description of the bug:

do_io() declares comp_time without initializing it:

struct timespec comp_time;

It is only ever written on two paths:

• wait_for_completions() — called only when the queue is full or when
  polling (full || io_in_polling(td)), and
• io_queue_event()'s FIO_Q_COMPLETED path — only for inline
  completions.

There is a common workload shape that takes neither path before
check_min_rate() reads the variable: an async engine on a block device
with a rate limit and rate_iops_min/ratemin set, e.g.

[global]
ioengine=libaio
rw=randwrite
bs=16k
direct=1
time_based=1
runtime=60
iodepth=16
rate_iops=500
rate_iops_min=500

[job]
filename=/dev/nvme1n1
write_lat_log=job

At 500 IOPS with iodepth=16 the queue is never full, 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
td->bytes_done is non-zero, the loop bottom calls
check_min_rate(td, &comp_time) and the settle check in
__check_min_rate() computes

if (mtime_since(&td->start, now) < 2000)   /* now == &comp_time */

from whatever bytes happened to be on the stack. 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.
fio: pid=..., got signal=6

When the garbage happens to be numerically benign, there is no crash but
the settle/rate arithmetic is still computed from garbage.

We hit the crashing variant in CI with fio 3.42 : every run of the
job above SIGABRT'd ~100 ms after start, on every instance,
deterministically (same code path, same stack leftovers). The same
binary and job on a different host runs fine — which is exactly what an
uninitialized stack read predicts. The code is the same in current
master and at least as far back as 3.38; the 3.38 -> 3.42 upgrade merely
changed the stack layout enough to make the leftover bytes poisonous for
this workload.

Backtrace from a production core (fio-3.42, x86_64):

#4  0x000000000040e274 in rel_time_since (...) at gettime.c:530
#5  0x000000000041f148 in rel_time_since (...) at gettime.c:540
#6  mtime_since (...) at gettime.c:541
#7  mtime_since_now (...) at gettime.c:512
#8  time_since_now (...) at gettime.c:546
#9  0x000000000040f562 in __check_min_rate (ddir=DDIR_WRITE, now=0x7ffedd67e580, td=0x7fe7a43ba000) at backend.c:176
#10 check_min_rate (...) at backend.c:226
#11 do_io (...) at backend.c:1315
#12 0x0000000000475c9e in thread_main (...) at backend.c:2096

In the core, td->start is sane and comp_time is stack garbage:

(gdb) frame 11
(gdb) print comp_time
$1 = {tv_sec = 140632831934736, tv_nsec = 4835703278458516699}
(gdb) print td->start
$2 = {tv_sec = 0, tv_nsec = 108700203}

Deterministic reproduction (since the natural trigger depends on
stack leftovers): poison comp_time at do_io() entry with the values
observed in the core,

struct timespec comp_time = { .tv_sec = 140632831934736, .tv_nsec = 4835703278458516699LL };

then run the job file above against any block device (a loop device
works). Reproduces the exact assertion and SIGABRT on the first rate
check, on current master.

Suggested fix:

Minimal crash fix: initialize comp_time at do_io() entry
(fio_gettime(&comp_time, NULL);). During the 2s settle window a stale
value is harmless (mtime_since clamps negative to 0 and the settle
check just stays in the settle period).

Worth noting while fixing: on this workload shape comp_time is never
updated at all (completions are only ever reaped by io_u_quiesce()),
so even with the crash fixed, spent = mtime_since(&td->last_rate_check_time, now)
stays near zero and the min-rate check never fires. If min-rate
enforcement is intended to work with quiesce-reaped completions, the
rate path needs to stamp a completion time too (or check_min_rate()
should take a fresh fio_gettime() when the passed time predates the
last check).

Environment:

Amazon Linux 2023, x86_64 (EC2); also reproduced (with the poison
above) on an Amazon Linux 2 dev host.

fio version:

fio-3.42 (crash observed in production); code identical in current
master and present since at least fio-3.38.

Was blktrace being run in parallel?:

No.

[vincentkfu]

The patch does fix the crash but as far as I can tell comp_time is never stamped with a real value for this workload, so rate_min remains in the settle period for the entire duration and the rate is never actually checked.

Would it not be better to find a way to give rate_min valid data to work with?

With the patch applied and the minimum rate check in init.c:fixup_options() nullified I can run the following with rate_iops=500 rate_iops_min=1000:

# ./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%