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.
 
        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
 ~~~~~~~~~~~~~~~~~~
 
 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`.
 
        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,
 .. 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;
 
        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));
        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->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);
        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->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);
        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->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);
        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.
 \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
 .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.
 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,
 .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 */
 
        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;
        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 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
 
 #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;
        }
 
                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));
        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,
        },
                .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",
        {
                .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;
 
        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);
 
        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.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);
        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);
        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 */
        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->thread_number = td->thread_number;
                        ts->groupid = td->groupid;

+                       ts->job_start = td->job_start;

 
                        /*
                         * first pid in group, not very useful...
 
                        /*
                         * 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 = 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;
                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;
        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;
        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 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;
        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 iodepth_batch_complete_min;
        uint32_t iodepth_batch_complete_max;
        uint32_t serialize_overlap;

-       uint32_t pad;

 
        uint64_t size;
        uint64_t io_size;
 
        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 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;
        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];
 
        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];
 
        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;
        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 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;
        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 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];
        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);
 }
 
        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);
        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;

        }
 }
 
        }
 }