Record job start time obtained via clock_gettime to fix time pain points

Add a new key in the json per-job output, clock_gettime_job_start, that
records the job start time obtained via a call to clock_gettime using
the clock_id specified by the 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.

Rename the alternate_epoch_clock_id option to clock_id, as now this
clock_id serves two purposes. The primary purpose is to be the clock_id
for recording clock_gettime_job_start. The secondary purpose is to be
the clock_id used if log_alternate_epoch is specified, in which case
each log file timestamp is based on the epoch specified by clock_id.
(Each such timestamp is obtained by taking the traditional zero-based
timestamps and adding clock_gettime_job_start to them.)

We also make log_unix_epoch an official alias of log_alternate_epoch,
instead of maintaining both redundant options.

Fixes #1544

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

HOWTO.rst

@@ -4103,22 +4103,24 @@ Measurements and reporting
 
 .. option:: log_unix_epoch=bool
 
- If set, fio will log Unix timestamps to the log files produced by enabling
- write_type_log for each log type, instead of the default zero-based
- timestamps.
+ Backwards compatible alias for log_alternate_epoch.
 
 .. option:: log_alternate_epoch=bool
 
- If set, fio will log timestamps based on the epoch used by the clock specified
- in the log_alternate_epoch_clock_id option, to the log files produced by
- enabling write_type_log for each log type, instead of the default zero-based
- timestamps.
+ If set, fio will log timestamps based on the epoch used by the clock
+ specified in the clock_id option, to the log files produced by enabling
+  write_type_log for each log type, instead of the default zero-based
+ timestamps.
 
 .. option:: log_alternate_epoch_clock_id=int
 
- Specifies the clock_id to be used by clock_gettime to obtain the alternate epoch
- if either log_unix_epoch or log_alternate_epoch are true. Otherwise has no
- effect. Default value is 0, or CLOCK_REALTIME.
+ Backwards compatible alias for clock_id.
+
+.. option:: clock_id=int
+
+ Specifies the clock_id to be used by clock_gettime to obtain the start time
+ of a job via clock_gettime. Default value is 0, or CLOCK_REALTIME, which
+ yields times based on the unix epoch.
 
 .. option:: block_error_percentiles=bool
 

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

cconv.c

@@ -216,9 +216,8 @@ int convert_thread_options_to_cpu(struct thread_options *o,
  o->log_prio = le32_to_cpu(top->log_prio);
  o->log_gz = le32_to_cpu(top->log_gz);
  o->log_gz_store = le32_to_cpu(top->log_gz_store);
- 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->clock_id = le32_to_cpu(top->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);
@@ -455,9 +454,8 @@ void convert_thread_options_to_net(struct thread_options_pack *top,
  top->log_prio = cpu_to_le32(o->log_prio);
  top->log_gz = cpu_to_le32(o->log_gz);
  top->log_gz_store = cpu_to_le32(o->log_gz_store);
- 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->clock_id = cpu_to_le32(o->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);

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->clock_gettime_job_start = le64_to_cpu(src->clock_gettime_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);

fio.1

@@ -3795,20 +3795,20 @@ decompressed with fio, using the \fB\-\-inflate\-log\fR command line
 parameter. The files will be stored with a `.fz' suffix.
 .TP
 .BI log_unix_epoch \fR=\fPbool
-If set, fio will log Unix timestamps to the log files produced by enabling
-write_type_log for each log type, instead of the default zero-based
-timestamps.
+Backward-compatible alias for \fBlog_alternate_epoch\fR.
 .TP
 .BI log_alternate_epoch \fR=\fPbool
 If set, fio will log timestamps based on the epoch used by the clock specified
-in the \fBlog_alternate_epoch_clock_id\fR option, to the log files produced by
-enabling write_type_log for each log type, instead of the default zero-based
-timestamps.
+in the \fBclock_id\fR option, to the log files produced by enabling
+write_type_log for each log type, instead of the default zero-based timestamps.
 .TP
 .BI log_alternate_epoch_clock_id \fR=\fPint
-Specifies the clock_id to be used by clock_gettime to obtain the alternate epoch
-if either \fBBlog_unix_epoch\fR or \fBlog_alternate_epoch\fR are true. Otherwise has no
-effect. Default value is 0, or CLOCK_REALTIME.
+Backward-compatible alias for \fBclock_id\fR.
+.TP
+.BI clock_id \fR=\fPint
+Specifies the clock_id to be used by clock_gettime to obtain the start time of
+a job. Default value is 0, or CLOCK_REALTIME, which yields times based on the
+unix epoch.
 .TP
 .BI block_error_percentiles \fR=\fPbool
 If set, record errors in trim block-sized units from writes and trims and

fio.h

@@ -388,7 +388,7 @@ 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 clock_gettime_job_start; /* Time job was started, clock_gettime's clock_id epoch based. */
  struct timespec last_issue;
  long time_offset;
  struct timespec ts_cache;

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);
 
 #endif

libfio.c

@@ -148,7 +148,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.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));

options.c

@@ -4600,30 +4600,23 @@ struct fio_option fio_options[FIO_MAX_OPTS] = {
  .help = "Install libz-dev(el) to get compression support",
  },
 #endif
- {
- .name = "log_unix_epoch",
- .lname = "Log epoch unix",
- .type = FIO_OPT_BOOL,
- .off1 = offsetof(struct thread_options, log_unix_epoch),
- .help = "Use Unix time in log files",
- .category = FIO_OPT_C_LOG,
- .group = FIO_OPT_G_INVALID,
- },
  {
  .name = "log_alternate_epoch",
+ .alias = "log_unix_epoch",
  .lname = "Log epoch alternate",
  .type = FIO_OPT_BOOL,
  .off1 = offsetof(struct thread_options, log_alternate_epoch),
- .help = "Use alternate epoch time in log files. Uses the same epoch as that is used by clock_gettime with specified log_alternate_epoch_clock_id.",
+ .help = "Use alternate epoch time in log files. Uses the same epoch as that is used by clock_gettime with specified clock_id.",
  .category = FIO_OPT_C_LOG,
  .group = FIO_OPT_G_INVALID,
  },
  {
- .name = "log_alternate_epoch_clock_id",
- .lname = "Log alternate epoch clock_id",
+ .name = "clock_id",
+ .alias = "log_alternate_epoch_clock_id",
+ .lname = "clock_id",
  .type = FIO_OPT_INT,
- .off1 = offsetof(struct thread_options, log_alternate_epoch_clock_id),
- .help = "If log_alternate_epoch or log_unix_epoch is true, this option specifies the clock_id from clock_gettime whose epoch should be used. If neither of those is true, this option has no effect. Default value is 0, or CLOCK_REALTIME",
+ .off1 = offsetof(struct thread_options, clock_id),
+ .help = "Specifies the clock_id to be used by clock_gettime to obtain the start time of a job. Default value is 0, or CLOCK_REALTIME.",
  .category = FIO_OPT_C_LOG,
  .group = FIO_OPT_G_INVALID,
  },

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.clock_id);
  fio_getrusage(&td->ru_start);
  clear_io_state(td, 1);
 

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, "clock_gettime_job_start", ts->clock_gettime_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->clock_gettime_job_start = td->clock_gettime_job_start;
 
  /*
  * first pid in group, not very useful...
@@ -3044,11 +3046,13 @@ static void __add_log_sample(struct io_log *iolog, union io_sample_data data,
  cur_log = get_cur_log(iolog);
  if (cur_log) {
  struct io_sample *s;
+ bool add_alternate_epoch;
 
  s = get_sample(iolog, cur_log, cur_log->nr_samples);
 
  s->data = data;
- s->time = t + (iolog->td ? iolog->td->alternate_epoch : 0);
+ add_alternate_epoch = (iolog->td != NULL) && iolog->td->o.log_alternate_epoch;
+ s->time = t + (add_alternate_epoch ? iolog->td->clock_gettime_job_start : 0);
  io_sample_set_ddir(iolog, s, ddir);
  s->bs = bs;
  s->priority = priority;

stat.h

@@ -169,6 +169,7 @@ struct thread_stat {
  uint32_t error;
  uint32_t thread_number;
  uint32_t groupid;
+ uint64_t clock_gettime_job_start; /* Time job was started, clock_gettime's clock_id epoch based. */
  uint32_t pid;
  char description[FIO_JOBDESC_SIZE];
  uint32_t members;

thread_options.h

@@ -170,9 +170,8 @@ struct thread_options {
  unsigned int log_offset;
  unsigned int log_gz;
  unsigned int log_gz_store;
- unsigned int log_unix_epoch;
  unsigned int log_alternate_epoch;
- unsigned int log_alternate_epoch_clock_id;
+ unsigned int clock_id;
  unsigned int norandommap;
  unsigned int softrandommap;
  unsigned int bs_unaligned;
@@ -494,9 +493,9 @@ struct thread_options_pack {
  uint32_t log_offset;
  uint32_t log_gz;
  uint32_t log_gz_store;
- uint32_t log_unix_epoch;
+ uint32_t pad2;
  uint32_t log_alternate_epoch;
- uint32_t log_alternate_epoch_clock_id;
+ uint32_t clock_id;
  uint32_t norandommap;
  uint32_t softrandommap;
  uint32_t bs_unaligned;

time.c

@@ -172,15 +172,13 @@ 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 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(clock_id, &ts);
+ td->clock_gettime_job_start = (unsigned long long)(ts.tv_sec) * 1000 +
+ (unsigned long long)(ts.tv_nsec) / 1000000;
 }
 
 void fill_start_time(struct timespec *t)