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