Fix I/O replay timing

fio supports replaying I/Os from a previous invocation, captured either
via blktrace or via `write_iolog`. That support includes simulating the
timing of the I/Os, accomplished by using the I/O timestamps from the
log to insert delays in the submission path if necessary to match the
pacing of the previous session. The logic to calculate the elapsed time
between I/Os during replay is not accounting for the time spent in
submitting the I/O to the kernel; this causes large discrepancies in
playback timing. Playback can take 2x or more longer than the
original workload due to the progressively-larger drift from excessive
delays.

This change also includes fixes to additional issues in the same logic,
specifically not adjusting to the expected vs actual sleep time for
delays based on the post-adjusted delay value vs the original delay
value. Another change is to keep a cumulative adjustment factor for both
the I/O-to-I/O time (when it's larger than the log delay) and for the
expected vs actual sleep time for delays.

Link: #1537 (comment)

Signed-off-by: Adam Horshack ([email protected])

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)

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)

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];

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)

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;

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;

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)