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 <mogeb@fb.com>
Link: https://lore.kernel.org/r/20220407174031.599117-2-mogeb@fb.com
Signed-off-by: Jens Axboe <axboe@kernel.dk>

diff --git a/blktrace.c b/blktrace.c
index ead601304703d216dacee410b565e88d16eee929..619121c704a90f198585293d976dffbe1984ca30 100644 (file)
--- 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 776fb51f74208cc67945c6e2527da9dcf5c53c78..8830ff34ad428d98bf920ac04f492365b02fbf8d 100644 (file)
--- 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 724ec1fe165adea55d89bad646bd7eb020253577..f6023ee2ce6241398138d39134eaafe26e140998 100644 (file)
--- 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 a39863095ad3f8264e055b40c448031c9507cc9c..62cbd1b02fe78cd8fed2fbe827ba779c446ece19 100644 (file)
--- 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 *);