Record job start time to fix time pain points

Add a new key in the json per-job output, job_start, that records the
job start time obtained via a call to clock_gettime using the clock_id
specified by the new job_start_clock_id option. This allows times of fio
jobs and log entries to be compared/ordered against each other and
against other system events recorded against the same clock_id.

Add a note to the documentation for group_reporting about how there are
several per-job values for which only the first job's value is recorded
in the json output format when group_reporting is enabled.

Fixes #1544

Signed-off-by: Nick Neumann nick@pcpartpicker.com

diff --git a/HOWTO.rst b/HOWTO.rst
index 89032941562d6311fab406664dda5db76e929e9f..9c825cc27dc6141242878f6e05f9e539b734ce03 100644 (file)
--- a/HOWTO.rst
+++ b/HOWTO.rst
@@ -755,6 +755,10 @@ Time related parameters
        calls will be excluded from other uses. Fio will manually clear it from the
        CPU mask of other jobs.
 
+.. option:: job_start_clock_id=int
+   The clock_id passed to the call to `clock_gettime` used to record job_start
+   in the `json` output format. Default is 0, or CLOCK_REALTIME.
+
 
 Target file/device
 ~~~~~~~~~~~~~~~~~~
@@ -3966,6 +3970,13 @@ Measurements and reporting
        same reporting group, unless if separated by a :option:`stonewall`, or by
        using :option:`new_group`.
 
+    NOTE: When :option: `group_reporting` is used along with `json` output,
+    there are certain per-job properties which can be different between jobs
+    but do not have a natural group-level equivalent. Examples include
+    `kb_base`, `unit_base`, `sig_figs`, `thread_number`, `pid`, and
+    `job_start`. For these properties, the values for the first job are
+    recorded for the group.
+
 .. option:: new_group
 
        Start a new reporting group. See: :option:`group_reporting`.  If not given,

diff --git a/backend.c b/backend.c
index 5f0740395bad36cd9d13c30bf6bb9d871805c785..a5895fec4d5d44096d1c67145b65a82180c100b0 100644 (file)
--- a/backend.c
+++ b/backend.c
@@ -1858,7 +1858,7 @@ static void *thread_main(void *data)
        if (rate_submit_init(td, sk_out))
                goto err;
 
-       set_epoch_time(td, o->log_unix_epoch | o->log_alternate_epoch, o->log_alternate_epoch_clock_id);
+       set_epoch_time(td, o->log_alternate_epoch_clock_id, o->job_start_clock_id);
        fio_getrusage(&td->ru_start);
        memcpy(&td->bw_sample_time, &td->epoch, sizeof(td->epoch));
        memcpy(&td->iops_sample_time, &td->epoch, sizeof(td->epoch));

diff --git a/cconv.c b/cconv.c
index ce6acbe6abd0d829966c49f016571ee3057ccd1d..b0127dd870f8c48252a9bfe7b8d44ccbdad0837d 100644 (file)
--- a/cconv.c
+++ b/cconv.c
@@ -219,6 +219,7 @@ int convert_thread_options_to_cpu(struct thread_options *o,
        o->log_unix_epoch = le32_to_cpu(top->log_unix_epoch);
        o->log_alternate_epoch = le32_to_cpu(top->log_alternate_epoch);
        o->log_alternate_epoch_clock_id = le32_to_cpu(top->log_alternate_epoch_clock_id);
+       o->job_start_clock_id = le32_to_cpu(top->job_start_clock_id);
        o->norandommap = le32_to_cpu(top->norandommap);
        o->softrandommap = le32_to_cpu(top->softrandommap);
        o->bs_unaligned = le32_to_cpu(top->bs_unaligned);
@@ -458,6 +459,7 @@ void convert_thread_options_to_net(struct thread_options_pack *top,
        top->log_unix_epoch = cpu_to_le32(o->log_unix_epoch);
        top->log_alternate_epoch = cpu_to_le32(o->log_alternate_epoch);
        top->log_alternate_epoch_clock_id = cpu_to_le32(o->log_alternate_epoch_clock_id);
+       top->job_start_clock_id = cpu_to_le32(o->job_start_clock_id);
        top->norandommap = cpu_to_le32(o->norandommap);
        top->softrandommap = cpu_to_le32(o->softrandommap);
        top->bs_unaligned = cpu_to_le32(o->bs_unaligned);

diff --git a/client.c b/client.c
index c257036bf5fa6524659ff9beb524945f8e06920c..345fa9101bdaf1dd210d690ee33b4749086d24f1 100644 (file)
--- a/client.c
+++ b/client.c
@@ -956,6 +956,7 @@ static void convert_ts(struct thread_stat *dst, struct thread_stat *src)
        dst->error              = le32_to_cpu(src->error);
        dst->thread_number      = le32_to_cpu(src->thread_number);
        dst->groupid            = le32_to_cpu(src->groupid);
+       dst->job_start          = le64_to_cpu(src->job_start);
        dst->pid                = le32_to_cpu(src->pid);
        dst->members            = le32_to_cpu(src->members);
        dst->unified_rw_rep     = le32_to_cpu(src->unified_rw_rep);

diff --git a/fio.1 b/fio.1
index f0dc49ab004cdeafc3b17d23709065aa4ef6e25a..3e5b840c94bc2c71b4bc97a36e789b4f5f96021d 100644 (file)
--- a/fio.1
+++ b/fio.1
@@ -537,6 +537,10 @@ copy that segment, instead of entering the kernel with a
 \fBgettimeofday\fR\|(2) call. The CPU set aside for doing these time
 calls will be excluded from other uses. Fio will manually clear it from the
 CPU mask of other jobs.
+.TP
+.BI job_start_clock_id \fR=\fPint
+The clock_id passed to the call to \fBclock_gettime\fR used to record job_start
+in the \fBjson\fR output format. Default is 0, or CLOCK_REALTIME.
 .SS "Target file/device"
 .TP
 .BI directory \fR=\fPstr
@@ -3664,6 +3668,15 @@ quickly becomes unwieldy. To see the final report per-group instead of
 per-job, use \fBgroup_reporting\fR. Jobs in a file will be part of the
 same reporting group, unless if separated by a \fBstonewall\fR, or by
 using \fBnew_group\fR.
+.RS
+.P
+NOTE: When \fBgroup_reporting\fR is used along with \fBjson\fR output, there
+are certain per-job properties which can be different between jobs but do not
+have a natural group-level equivalent. Examples include \fBkb_base\fR,
+\fBunit_base\fR, \fBsig_figs\fR, \fBthread_number\fR, \fBpid\fR, and
+\fBjob_start\fR. For these properties, the values for the first job are
+recorded for the group.
+.RE
 .TP
 .BI new_group
 Start a new reporting group. See: \fBgroup_reporting\fR. If not given,

diff --git a/fio.h b/fio.h
index a54f57c93e3e0f40e076d19b230f4933e6782dab..1322656fd4497501577804124438f38f55765e93 100644 (file)
--- a/fio.h
+++ b/fio.h
@@ -388,7 +388,8 @@ struct thread_data {
 
        struct timespec start;  /* start of this loop */
        struct timespec epoch;  /* time job was started */
-       unsigned long long alternate_epoch; /* Time job was started, clock_gettime's clock_id epoch based. */
+       unsigned long long alternate_epoch; /* Time job was started, as clock_gettime(log_alternate_epoch_clock_id) */
+       unsigned long long job_start; /* Time job was started, as clock_gettime(job_start_clock_id) */
        struct timespec last_issue;
        long time_offset;
        struct timespec ts_cache;

diff --git a/fio_time.h b/fio_time.h
index 62d92120a5ac40b1e22cd8db33d0167eb6a78a66..b20e734c4a8a3053cd4262458575e670710a8e7c 100644 (file)
--- a/fio_time.h
+++ b/fio_time.h
@@ -30,6 +30,6 @@ extern bool ramp_time_over(struct thread_data *);
 extern bool in_ramp_time(struct thread_data *);
 extern void fio_time_init(void);
 extern void timespec_add_msec(struct timespec *, unsigned int);
-extern void set_epoch_time(struct thread_data *, int, clockid_t);
+extern void set_epoch_time(struct thread_data *, clockid_t, clockid_t);
 
 #endif

diff --git a/libfio.c b/libfio.c
index 237ce34cb3bb9dc42599309683ca807850a1af5d..5c4332776983377240770c1259a0b4e31e4976c7 100644 (file)
--- a/libfio.c
+++ b/libfio.c
@@ -149,7 +149,7 @@ void reset_all_stats(struct thread_data *td)
                td->ts.runtime[i] = 0;
        }
 
-       set_epoch_time(td, td->o.log_unix_epoch | td->o.log_alternate_epoch, td->o.log_alternate_epoch_clock_id);
+       set_epoch_time(td, td->o.log_alternate_epoch_clock_id, td->o.job_start_clock_id);
        memcpy(&td->start, &td->epoch, sizeof(td->epoch));
        memcpy(&td->iops_sample_time, &td->epoch, sizeof(td->epoch));
        memcpy(&td->bw_sample_time, &td->epoch, sizeof(td->epoch));

diff --git a/options.c b/options.c
index 48aa0d7b1ccaf2d7a8041a2b383bafdf31ca7a5f..281ea609e41d4334f44b83679a2483707cdbf9a9 100644 (file)
--- a/options.c
+++ b/options.c
@@ -4952,6 +4952,16 @@ struct fio_option fio_options[FIO_MAX_OPTS] = {
                .category = FIO_OPT_C_GENERAL,
                .group  = FIO_OPT_G_CLOCK,
        },
+       {
+               .name   = "job_start_clock_id",
+               .lname  = "Job start clock_id",
+               .type   = FIO_OPT_INT,
+               .off1   = offsetof(struct thread_options, job_start_clock_id),
+               .help   = "The clock_id passed to the call to clock_gettime used to record job_start in the json output format. Default is 0, or CLOCK_REALTIME",
+               .verify = gtod_cpu_verify,
+               .category = FIO_OPT_C_GENERAL,
+               .group  = FIO_OPT_G_CLOCK,
+       },
        {
                .name   = "unified_rw_reporting",
                .lname  = "Unified RW Reporting",

diff --git a/rate-submit.c b/rate-submit.c
index 6f6d15bd660fbaa1ed504530edd3f3f6b38822aa..92be3df75ebc181a653c5b745d15c84c9d7b97d2 100644 (file)
--- a/rate-submit.c
+++ b/rate-submit.c
@@ -185,7 +185,7 @@ static int io_workqueue_init_worker_fn(struct submit_worker *sw)
        if (td->io_ops->post_init && td->io_ops->post_init(td))
                goto err_io_init;
 
-       set_epoch_time(td, td->o.log_unix_epoch | td->o.log_alternate_epoch, td->o.log_alternate_epoch_clock_id);
+       set_epoch_time(td, td->o.log_alternate_epoch_clock_id, td->o.job_start_clock_id);
        fio_getrusage(&td->ru_start);
        clear_io_state(td, 1);
 

diff --git a/server.c b/server.c
index bb423702a714224306445bbffeb12d174215c1fe..27332e326e9b8db29c37084fe13d04d6535ad73d 100644 (file)
--- a/server.c
+++ b/server.c
@@ -1706,6 +1706,7 @@ void fio_server_send_ts(struct thread_stat *ts, struct group_run_stats *rs)
        p.ts.error              = cpu_to_le32(ts->error);
        p.ts.thread_number      = cpu_to_le32(ts->thread_number);
        p.ts.groupid            = cpu_to_le32(ts->groupid);
+       p.ts.job_start          = cpu_to_le64(ts->job_start);
        p.ts.pid                = cpu_to_le32(ts->pid);
        p.ts.members            = cpu_to_le32(ts->members);
        p.ts.unified_rw_rep     = cpu_to_le32(ts->unified_rw_rep);

diff --git a/stat.c b/stat.c
index 7b791628f4f7ca776c8f22ca5e609d6e0a5904cf..8c8d69f0473ab8f33eaa0828d5e1a66065241145 100644 (file)
--- a/stat.c
+++ b/stat.c
@@ -1712,6 +1712,7 @@ static struct json_object *show_thread_status_json(struct thread_stat *ts,
        root = json_create_object();
        json_object_add_value_string(root, "jobname", ts->name);
        json_object_add_value_int(root, "groupid", ts->groupid);
+       json_object_add_value_int(root, "job_start", ts->job_start);
        json_object_add_value_int(root, "error", ts->error);
 
        /* ETA Info */
@@ -2526,6 +2527,7 @@ void __show_run_stats(void)
                         */
                        ts->thread_number = td->thread_number;
                        ts->groupid = td->groupid;
+                       ts->job_start = td->job_start;
 
                        /*
                         * first pid in group, not very useful...
@@ -3048,7 +3050,9 @@ static void __add_log_sample(struct io_log *iolog, union io_sample_data data,
                s = get_sample(iolog, cur_log, cur_log->nr_samples);
 
                s->data = data;
-               s->time = t + (iolog->td ? iolog->td->alternate_epoch : 0);
+               s->time = t;
+               if (iolog->td && (iolog->td->o.log_unix_epoch || iolog->td->o.log_alternate_epoch))
+                       s->time += iolog->td->alternate_epoch;
                io_sample_set_ddir(iolog, s, ddir);
                s->bs = bs;
                s->priority = priority;

diff --git a/stat.h b/stat.h
index 8ceabc48c7e0fd393ee8a307b6f6fdb0acdccab6..bd986d4e71c9b7f1b9b42174df33076143396f65 100644 (file)
--- a/stat.h
+++ b/stat.h
@@ -169,6 +169,7 @@ struct thread_stat {
        uint32_t error;
        uint32_t thread_number;
        uint32_t groupid;
+       uint64_t job_start; /* Time job was started, as clock_gettime(job_start_clock_id) */
        uint32_t pid;
        char description[FIO_JOBDESC_SIZE];
        uint32_t members;

diff --git a/thread_options.h b/thread_options.h
index 38a9993d23a3eef4395d450ed73253a1d1ee5e2a..91c194cf7197df780c07e76cd23b168fdb33f535 100644 (file)
--- a/thread_options.h
+++ b/thread_options.h
@@ -273,6 +273,7 @@ struct thread_options {
        unsigned int unified_rw_rep;
        unsigned int gtod_reduce;
        unsigned int gtod_cpu;
+       unsigned int job_start_clock_id;
        enum fio_cs clocksource;
        unsigned int no_stall;
        unsigned int trim_percentage;
@@ -422,7 +423,6 @@ struct thread_options_pack {
        uint32_t iodepth_batch_complete_min;
        uint32_t iodepth_batch_complete_max;
        uint32_t serialize_overlap;
-       uint32_t pad;
 
        uint64_t size;
        uint64_t io_size;
@@ -433,13 +433,11 @@ struct thread_options_pack {
        uint32_t fill_device;
        uint32_t file_append;
        uint32_t unique_filename;
-       uint32_t pad3;
        uint64_t file_size_low;
        uint64_t file_size_high;
        uint64_t start_offset;
        uint64_t start_offset_align;
        uint32_t start_offset_nz;
-       uint32_t pad4;
 
        uint64_t bs[DDIR_RWDIR_CNT];
        uint64_t ba[DDIR_RWDIR_CNT];
@@ -511,6 +509,7 @@ struct thread_options_pack {
        struct zone_split zone_split[DDIR_RWDIR_CNT][ZONESPLIT_MAX];
        uint32_t zone_split_nr[DDIR_RWDIR_CNT];
 
+       uint32_t pad;
        fio_fp64_t zipf_theta;
        fio_fp64_t pareto_h;
        fio_fp64_t gauss_dev;
@@ -593,6 +592,7 @@ struct thread_options_pack {
        uint32_t unified_rw_rep;
        uint32_t gtod_reduce;
        uint32_t gtod_cpu;
+       uint32_t job_start_clock_id;
        uint32_t clocksource;
        uint32_t no_stall;
        uint32_t trim_percentage;
@@ -603,6 +603,7 @@ struct thread_options_pack {
        uint32_t lat_percentiles;
        uint32_t slat_percentiles;
        uint32_t percentile_precision;
+       uint32_t pad2;
        fio_fp64_t percentile_list[FIO_IO_U_LIST_MAX_LEN];
 
        uint8_t read_iolog_file[FIO_TOP_STR_MAX];

diff --git a/time.c b/time.c
index 5c4d6de0399c5cc681e9ca362c019870baf9db98..7cbab6ff4f9ea1d029e7d9d2c0253278061ffe60 100644 (file)
--- a/time.c
+++ b/time.c
@@ -172,14 +172,22 @@ void set_genesis_time(void)
        fio_gettime(&genesis, NULL);
 }
 
-void set_epoch_time(struct thread_data *td, int log_alternate_epoch, clockid_t clock_id)
+void set_epoch_time(struct thread_data *td, clockid_t log_alternate_epoch_clock_id, clockid_t job_start_clock_id)
 {
+       struct timespec ts;
        fio_gettime(&td->epoch, NULL);
-       if (log_alternate_epoch) {
-               struct timespec ts;
-               clock_gettime(clock_id, &ts);
-               td->alternate_epoch = (unsigned long long)(ts.tv_sec) * 1000 +
-                                (unsigned long long)(ts.tv_nsec) / 1000000;
+       clock_gettime(log_alternate_epoch_clock_id, &ts);
+       td->alternate_epoch = (unsigned long long)(ts.tv_sec) * 1000 +
+                                                 (unsigned long long)(ts.tv_nsec) / 1000000;
+       if (job_start_clock_id == log_alternate_epoch_clock_id)
+       {
+               td->job_start = td->alternate_epoch;
+       }
+       else
+       {
+               clock_gettime(job_start_clock_id, &ts);
+               td->job_start = (unsigned long long)(ts.tv_sec) * 1000 +
+                                               (unsigned long long)(ts.tv_nsec) / 1000000;
        }
 }