From 6d608dd93566c97f11907dbeee2e7085ec89f395 Mon Sep 17 00:00:00 2001 From: Horshack Date: Tue, 7 Mar 2023 12:18:46 -0500 Subject: [PATCH] Fix I/O replay timing fio supports replaying I/Os from a previous invocation, captured either via blktrace or `write_iolog`. That support includes simulating the timing between I/Os by using the running timestamps from the capture log, recreating that timing by inserting delays in the replay submission path if necessary. The calculation for how much delay to insert is based on how long it takes to complete the most recent replayed I/O, as compared to the how long that same I/O took in the original workload recorded in the log. The issue is in iolog_delay(). It calculates the replay I/O execution time starting from just after issuing I/O to the kernel in td_io_queue() until the start of iolog_delay(). This excludes the time it actually took for the kernel to process the submission, which depending on the I/O engine can be significant. Because this time was under-measured, iolog_delay()'s added more delay than needed, since it thought the replay was executing too fast vs the logged I/O. This issue causes the total replay to take 2x or longer than the original workload due to the progressively-larger drift from these excessive delays. The fix is to change iolog_delay() to use the full execution path time for an I/O, including the kernel submission time. This is accomplished by removing the existing points where the replay I/O clock is started (td_io_queue and the async engines) and moving that into iolog_delay(). This means we're no longer technically matching the precise stage in the I/O path for replay vs the original workload, but this doesn't really matter since that's only an initial time skew reflected in the very first I/O operation. After that we only need to match the inter-I/O pacing. This change includes fixes to additional issues found in iolog_delay(): 1) The logic that measures how long usec_sleep() takes relative to how much sleep was requested was comparing against the original log delay value instead of the value adjusted by the last replay execution I/O, causing an under-adjustment when usec_sleep() took longer than requested, creating more total delay than necessary. 2) The logic wasn't accumulating the usec_sleep() adjustment from the above step across more than one replayed I/O. It would reset the adjustment to zero on the next I/O. I guess the logic was assuming the adjustment would never be larger than a single log delay interval. It also wasn't accumulating the replay I/O execution time across more than one interval, so for example if a replay I/O took 3x longer than the log I/O it would only adjust that down to a zero delay for one replay I/O, causing the 2x difference to never be accounted for and thus add to the total running replay time. Link: https://github.com/axboe/fio/issues/1537#issuecomment-1461092644 Signed-off-by: Adam Horshack (horshack@live.com) --- engines/io_uring.c | 6 ------ engines/libaio.c | 6 ------ engines/librpma_fio.c | 10 ---------- engines/rdma.c | 6 ------ init.c | 7 ------- ioengines.c | 20 ++------------------ iolog.c | 28 +++++++++++++++------------- 7 files changed, 17 insertions(+), 66 deletions(-) diff --git a/engines/io_uring.c b/engines/io_uring.c index 5393758aa6..0ee5a82227 100644 --- a/engines/io_uring.c +++ b/engines/io_uring.c @@ -613,12 +613,6 @@ static void fio_ioring_queued(struct thread_data *td, int start, int nr) start++; } - - /* - * only used for iolog - */ - if (td->o.read_iolog_file) - memcpy(&td->last_issue, &now, sizeof(now)); } static int fio_ioring_commit(struct thread_data *td) diff --git a/engines/libaio.c b/engines/libaio.c index 33b8c12f96..da5279f485 100644 --- a/engines/libaio.c +++ b/engines/libaio.c @@ -368,12 +368,6 @@ static void fio_libaio_queued(struct thread_data *td, struct io_u **io_us, memcpy(&io_u->issue_time, &now, sizeof(now)); io_u_queued(td, io_u); } - - /* - * only used for iolog - */ - if (td->o.read_iolog_file) - memcpy(&td->last_issue, &now, sizeof(now)); } static int fio_libaio_commit(struct thread_data *td) diff --git a/engines/librpma_fio.c b/engines/librpma_fio.c index 42d6163ea1..3e7ec16696 100644 --- a/engines/librpma_fio.c +++ b/engines/librpma_fio.c @@ -597,16 +597,6 @@ int librpma_fio_client_commit(struct thread_data *td) } } - if ((fill_time = fio_fill_issue_time(td))) { - fio_gettime(&now, NULL); - - /* - * only used for iolog - */ - if (td->o.read_iolog_file) - memcpy(&td->last_issue, &now, sizeof(now)); - - } /* move executed io_us from queued[] to flight[] */ for (i = 0; i < ccd->io_u_queued_nr; i++) { struct io_u *io_u = ccd->io_us_queued[i]; diff --git a/engines/rdma.c b/engines/rdma.c index fcb4106889..dd088e6aba 100644 --- a/engines/rdma.c +++ b/engines/rdma.c @@ -832,12 +832,6 @@ static void fio_rdmaio_queued(struct thread_data *td, struct io_u **io_us, memcpy(&io_u->issue_time, &now, sizeof(now)); io_u_queued(td, io_u); } - - /* - * only used for iolog - */ - if (td->o.read_iolog_file) - memcpy(&td->last_issue, &now, sizeof(now)); } static int fio_rdmaio_commit(struct thread_data *td) diff --git a/init.c b/init.c index 442dab4273..549a25600f 100644 --- a/init.c +++ b/init.c @@ -628,13 +628,6 @@ static int fixup_options(struct thread_data *td) } #endif - if (o->write_iolog_file && o->read_iolog_file) { - log_err("fio: read iolog overrides write_iolog\n"); - free(o->write_iolog_file); - o->write_iolog_file = NULL; - ret |= warnings_fatal; - } - if (o->zone_mode == ZONE_MODE_NONE && o->zone_size) { log_err("fio: --zonemode=none and --zonesize are not compatible.\n"); ret |= 1; diff --git a/ioengines.c b/ioengines.c index e2316ee4e3..f5719baf4c 100644 --- a/ioengines.c +++ b/ioengines.c @@ -358,16 +358,8 @@ enum fio_q_status td_io_queue(struct thread_data *td, struct io_u *io_u) if (td_ioengine_flagged(td, FIO_SYNCIO) || async_ioengine_sync_trim(td, io_u)) { - if (fio_fill_issue_time(td)) { + if (fio_fill_issue_time(td)) fio_gettime(&io_u->issue_time, NULL); - - /* - * only used for iolog - */ - if (td->o.read_iolog_file) - memcpy(&td->last_issue, &io_u->issue_time, - sizeof(io_u->issue_time)); - } } @@ -444,16 +436,8 @@ enum fio_q_status td_io_queue(struct thread_data *td, struct io_u *io_u) if (!td_ioengine_flagged(td, FIO_SYNCIO) && !async_ioengine_sync_trim(td, io_u)) { if (fio_fill_issue_time(td) && - !td_ioengine_flagged(td, FIO_ASYNCIO_SETS_ISSUE_TIME)) { + !td_ioengine_flagged(td, FIO_ASYNCIO_SETS_ISSUE_TIME)) fio_gettime(&io_u->issue_time, NULL); - - /* - * only used for iolog - */ - if (td->o.read_iolog_file) - memcpy(&td->last_issue, &io_u->issue_time, - sizeof(io_u->issue_time)); - } } return ret; diff --git a/iolog.c b/iolog.c index cc2cbc65ef..8268330528 100644 --- a/iolog.c +++ b/iolog.c @@ -80,23 +80,23 @@ void log_file(struct thread_data *td, struct fio_file *f, static void iolog_delay(struct thread_data *td, unsigned long delay) { - uint64_t usec = utime_since_now(&td->last_issue); - unsigned long orig_delay = delay; + uint64_t usec; + unsigned long delay_wanted; uint64_t this_delay; - struct timespec ts; + struct timespec ts, ts_after_sleep; - if (delay < td->time_offset) { - td->time_offset = 0; - return; - } + fio_gettime(&ts, NULL); + usec = utime_since(&td->last_issue, &ts) + td->time_offset; - delay -= td->time_offset; - if (delay < usec) + if (delay <= usec) { + td->time_offset = usec-delay; + td->last_issue = ts; return; + } delay -= usec; - fio_gettime(&ts, NULL); + delay_wanted = delay; while (delay && !td->terminate) { this_delay = delay; if (this_delay > 500000) @@ -106,11 +106,13 @@ static void iolog_delay(struct thread_data *td, unsigned long delay) delay -= this_delay; } - usec = utime_since_now(&ts); - if (usec > orig_delay) - td->time_offset = usec - orig_delay; + fio_gettime(&ts_after_sleep, NULL); + usec = utime_since(&ts, &ts_after_sleep); + if (usec > delay_wanted) + td->time_offset = usec - delay_wanted; else td->time_offset = 0; + td->last_issue = ts_after_sleep; } static int ipo_special(struct thread_data *td, struct io_piece *ipo)