Inflight_issued does not match

[efeng2001]

Description of the bug:
inflight_issued does not match: numberio=0, inflight_issued=1329237
Given a ramp time, the numberio suddenly dropped to 0 and inflight_issued has not.

Environment: x86_64 with HUS726060ALE611

fio version: 3.41

Reproduction steps
Reproduced the issue at HDD with libaio.

From logs, numberio suddenly drop to 0.

verify 3144985 invalidate_inflight: numberio=3528, inflight_idx=198
verify 3144985 using already filled verify pattern b=4 len=4096
verify 3144985 log_inflight: numberio=3857, inflight_idx=198
verify 3144985 invalidate_inflight: numberio=3568, inflight_idx=425
verify 3144985 using already filled verify pattern b=4 len=4096
inflight_issued does not match: numberio=0, inflight_issued=3858
Add logs into reset_all_stats, confirmed numberio is cleaned up in this function.

verify 3146758 using already filled verify pattern b=4 len=4096
verify 3146758 log_inflight: numberio=3749, inflight_idx=66
verify 3146758 reset_all_stats: b462235793-hdd
verify 3146758 invalidate_inflight: numberio=3391, inflight_idx=412
verify 3146758 using already filled verify pattern b=4 len=4096
inflight_issued does not match: numberio=0, inflight_issued=3750
Add logs into ramp_time_over, confirmed reset_all_stats is called in this function.

verify 3150767 using already filled verify pattern b=4 len=4096
verify 3150767 log_inflight: numberio=3538, inflight_idx=21
verify 3150767 invalidate_inflight: numberio=3529, inflight_idx=19
verify 3150767 ramp_time_over: b462235793-hdd
verify 3150767 reset_all_stats: b462235793-hdd
verify 3150767 using already filled verify pattern b=4 len=4096
inflight_issued does not match: numberio=0, inflight_issued=3539
Commented out ramp=9, passed.

Disk stats (read/write):
sdb: ios=0/3907, sectors=0/31256, merge=0/0, ticks=0/314332, in_queue=314331, util=99.07%

[minwooim]

How about the fix below? looks like missing to clear inflight_issued

diff --git a/libfio.c b/libfio.c
index 57f3f858dcfc..4726fa1e5e7b 100644
--- a/libfio.c
+++ b/libfio.c
@@ -161,6 +161,7 @@ void reset_all_stats(struct thread_data *td)
        lat_target_reset(td);
        clear_rusage_stat(td);
        helper_reset();
+       clear_inflight(td);
 }

 void reset_fio_state(void)

[efeng2001]

We had tried that fix. But apparently it will further caused a possible race condition when ramp time ends and with verfiy_save_sate on.

Config ran:

[global]
ioengine=libaio
direct=1
filename=./fio_test_file
size=64M
bs=4k
runtime=3s
verify=crc32
rw=write
time_based=1
group_reporting=1

[Test1-Ramp-VerifyStateSave=1]
description="Ramp time with verify_state_save=1"
ramp_time=1s
# verify_state_save=1 is default with verify=crc32

Result:

verify   138523 fill random bytes len=4096
verify   138523 fill crc32 io_u 0x562a127592c0, len 4096
verify   138523 log_inflight: numberio=7525, inflight_idx=0
verify   138523 Start reset_all_stats: numberio 0x7f0e760a67f0
verify   138523 End reset_all_stats: numberio 0x7f0e760a67f0
verify   138523 invalidate_inflight: numberio=7525, inflight_idx=0
inflight entry already invalid: numberio=7525, inflight_idx=0
fio: pid=138523, got signal=6

We are suspecting that when verify_sate_save and ramp_time are both set for testing, the following sequence might happened:

• An I/O is issued for writing. For example giving numberio = 5. log_inflight() stores 5 in td->inflight_numberio.
• FIO's ramp time ends, and reset_all_stats() is called before the I/O with numberio = 5 has completed.
• Because the if checks are missing, td->io_issues[DDIR_WRITE] is reset to 0, and clear_inflight(td) is called, wiping 5 from the td->inflight_numberio array.
• The I/O with numberio = 5 finally completes. The completion logic calls invalidate_inflight() to remove 5 from td->inflight_numberio.
• Problem: invalidate_inflight() searches td->inflight_numberio for 5, but it won't find it because clear_inflight() already wiped it.