From 315bbf01119ea783554d274add04db98c0a3b433 Mon Sep 17 00:00:00 2001 From: Mohamad Gebai Date: Thu, 7 Apr 2022 10:40:29 -0700 Subject: [PATCH] iolog: add version 3 to support timestamp-based replay Version 3 format looks as follows: timestamp filename action offset length All file and IO actions must have timestamps, including 'add'. The 'wait' action is not allowed with version 3 so that we can leave all timing functionality to timestamps. Signed-off-by: Mohamad Gebai Link: https://lore.kernel.org/r/20220407174031.599117-2-mogeb@fb.com Signed-off-by: Jens Axboe --- blktrace.c | 17 ++--------- fio.h | 3 +- iolog.c | 89 +++++++++++++++++++++++++++++++++++++++++++----------- iolog.h | 8 ++--- 4 files changed, 80 insertions(+), 37 deletions(-) diff --git a/blktrace.c b/blktrace.c index ead60130..619121c7 100644 --- a/blktrace.c +++ b/blktrace.c @@ -313,25 +313,14 @@ static bool queue_trace(struct thread_data *td, struct blk_io_trace *t, unsigned long *ios, unsigned long long *bs, struct file_cache *cache) { - unsigned long long *last_ttime = &td->io_log_blktrace_last_ttime; + unsigned long long *last_ttime = &td->io_log_last_ttime; unsigned long long delay = 0; if ((t->action & 0xffff) != __BLK_TA_QUEUE) return false; if (!(t->action & BLK_TC_ACT(BLK_TC_NOTIFY))) { - if (!*last_ttime || td->o.no_stall || t->time < *last_ttime) - delay = 0; - else if (td->o.replay_time_scale == 100) - delay = t->time - *last_ttime; - else { - double tmp = t->time - *last_ttime; - double scale; - - scale = (double) 100.0 / (double) td->o.replay_time_scale; - tmp *= scale; - delay = tmp; - } + delay = delay_since_ttime(td, t->time); *last_ttime = t->time; } @@ -422,7 +411,7 @@ bool init_blktrace_read(struct thread_data *td, const char *filename, int need_s goto err; } td->io_log_blktrace_swap = need_swap; - td->io_log_blktrace_last_ttime = 0; + td->io_log_last_ttime = 0; td->o.size = 0; free_release_files(td); diff --git a/fio.h b/fio.h index 776fb51f..8830ff34 100644 --- a/fio.h +++ b/fio.h @@ -431,10 +431,11 @@ struct thread_data { FILE *io_log_rfile; unsigned int io_log_blktrace; unsigned int io_log_blktrace_swap; - unsigned long long io_log_blktrace_last_ttime; + unsigned long long io_log_last_ttime; unsigned int io_log_current; unsigned int io_log_checkmark; unsigned int io_log_highmark; + unsigned int io_log_version; struct timespec io_log_highmark_time; /* diff --git a/iolog.c b/iolog.c index 724ec1fe..f6023ee2 100644 --- a/iolog.c +++ b/iolog.c @@ -31,6 +31,7 @@ static int iolog_flush(struct io_log *log); static const char iolog_ver2[] = "fio version 2 iolog"; +static const char iolog_ver3[] = "fio version 3 iolog"; void queue_io_piece(struct thread_data *td, struct io_piece *ipo) { @@ -116,6 +117,10 @@ static int ipo_special(struct thread_data *td, struct io_piece *ipo) f = td->files[ipo->fileno]; + if (ipo->delay) + iolog_delay(td, ipo->delay); + if (fio_fill_issue_time(td)) + fio_gettime(&td->last_issue, NULL); switch (ipo->file_action) { case FIO_LOG_OPEN_FILE: if (td->o.replay_redirect && fio_file_open(f)) { @@ -134,6 +139,11 @@ static int ipo_special(struct thread_data *td, struct io_piece *ipo) case FIO_LOG_UNLINK_FILE: td_io_unlink_file(td, f); break; + case FIO_LOG_ADD_FILE: + /* + * Nothing to do + */ + break; default: log_err("fio: bad file action %d\n", ipo->file_action); break; @@ -142,7 +152,25 @@ static int ipo_special(struct thread_data *td, struct io_piece *ipo) return 1; } -static bool read_iolog2(struct thread_data *td); +static bool read_iolog(struct thread_data *td); + +unsigned long long delay_since_ttime(const struct thread_data *td, + unsigned long long time) +{ + double tmp; + double scale; + const unsigned long long *last_ttime = &td->io_log_last_ttime; + + if (!*last_ttime || td->o.no_stall || time < *last_ttime) + return 0; + else if (td->o.replay_time_scale == 100) + return time - *last_ttime; + + + scale = (double) 100.0 / (double) td->o.replay_time_scale; + tmp = time - *last_ttime; + return tmp * scale; +} int read_iolog_get(struct thread_data *td, struct io_u *io_u) { @@ -158,7 +186,7 @@ int read_iolog_get(struct thread_data *td, struct io_u *io_u) if (!read_blktrace(td)) return 1; } else { - if (!read_iolog2(td)) + if (!read_iolog(td)) return 1; } } @@ -388,14 +416,20 @@ int64_t iolog_items_to_fetch(struct thread_data *td) return items_to_fetch; } +#define io_act(_td, _r) (((_td)->io_log_version == 3 && (r) == 5) || \ + ((_td)->io_log_version == 2 && (r) == 4)) +#define file_act(_td, _r) (((_td)->io_log_version == 3 && (r) == 3) || \ + ((_td)->io_log_version == 2 && (r) == 2)) + /* - * Read version 2 iolog data. It is enhanced to include per-file logging, + * Read version 2 and 3 iolog data. It is enhanced to include per-file logging, * syncs, etc. */ -static bool read_iolog2(struct thread_data *td) +static bool read_iolog(struct thread_data *td) { unsigned long long offset; unsigned int bytes; + unsigned long long delay = 0; int reads, writes, waits, fileno = 0, file_action = 0; /* stupid gcc */ char *rfname, *fname, *act; char *str, *p; @@ -422,14 +456,28 @@ static bool read_iolog2(struct thread_data *td) while ((p = fgets(str, 4096, td->io_log_rfile)) != NULL) { struct io_piece *ipo; int r; + unsigned long long ttime; - r = sscanf(p, "%256s %256s %llu %u", rfname, act, &offset, - &bytes); + if (td->io_log_version == 3) { + r = sscanf(p, "%llu %256s %256s %llu %u", &ttime, rfname, act, + &offset, &bytes); + delay = delay_since_ttime(td, ttime); + td->io_log_last_ttime = ttime; + /* + * "wait" is not allowed with version 3 + */ + if (!strcmp(act, "wait")) { + log_err("iolog: ignoring wait command with" + " version 3 for file %s\n", fname); + continue; + } + } else /* version 2 */ + r = sscanf(p, "%256s %256s %llu %u", rfname, act, &offset, &bytes); if (td->o.replay_redirect) fname = td->o.replay_redirect; - if (r == 4) { + if (io_act(td, r)) { /* * Check action first */ @@ -451,7 +499,7 @@ static bool read_iolog2(struct thread_data *td) continue; } fileno = get_fileno(td, fname); - } else if (r == 2) { + } else if (file_act(td, r)) { rw = DDIR_INVAL; if (!strcmp(act, "add")) { if (td->o.replay_redirect && @@ -462,7 +510,6 @@ static bool read_iolog2(struct thread_data *td) fileno = add_file(td, fname, td->subjob_number, 1); file_action = FIO_LOG_ADD_FILE; } - continue; } else if (!strcmp(act, "open")) { fileno = get_fileno(td, fname); file_action = FIO_LOG_OPEN_FILE; @@ -475,7 +522,7 @@ static bool read_iolog2(struct thread_data *td) continue; } } else { - log_err("bad iolog2: %s\n", p); + log_err("bad iolog%d: %s\n", td->io_log_version, p); continue; } @@ -506,6 +553,8 @@ static bool read_iolog2(struct thread_data *td) ipo = calloc(1, sizeof(*ipo)); init_ipo(ipo); ipo->ddir = rw; + if (td->io_log_version == 3) + ipo->delay = delay; if (rw == DDIR_WAIT) { ipo->delay = offset; } else { @@ -650,18 +699,22 @@ static bool init_iolog_read(struct thread_data *td, char *fname) } /* - * version 2 of the iolog stores a specific string as the + * versions 2 and 3 of the iolog store a specific string as the * first line, check for that */ - if (!strncmp(iolog_ver2, buffer, strlen(iolog_ver2))) { - free_release_files(td); - td->io_log_rfile = f; - return read_iolog2(td); + if (!strncmp(iolog_ver2, buffer, strlen(iolog_ver2))) + td->io_log_version = 2; + else if (!strncmp(iolog_ver3, buffer, strlen(iolog_ver3))) + td->io_log_version = 3; + else { + log_err("fio: iolog version 1 is no longer supported\n"); + fclose(f); + return false; } - log_err("fio: iolog version 1 is no longer supported\n"); - fclose(f); - return false; + free_release_files(td); + td->io_log_rfile = f; + return read_iolog(td); } /* diff --git a/iolog.h b/iolog.h index a3986309..62cbd1b0 100644 --- a/iolog.h +++ b/iolog.h @@ -227,10 +227,8 @@ struct io_piece { unsigned long len; unsigned int flags; enum fio_ddir ddir; - union { - unsigned long delay; - unsigned int file_action; - }; + unsigned long delay; + unsigned int file_action; }; /* @@ -259,6 +257,8 @@ extern int iolog_compress_init(struct thread_data *, struct sk_out *); extern void iolog_compress_exit(struct thread_data *); extern size_t log_chunk_sizes(struct io_log *); extern int init_io_u_buffers(struct thread_data *); +extern unsigned long long delay_since_ttime(const struct thread_data *, + unsigned long long); #ifdef CONFIG_ZLIB extern int iolog_file_inflate(const char *); -- 2.25.1