Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
wants to merge 1 commit into from
Closed

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Binary file added .HOWTO.rst.swp
View file
Open in desktop
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was accidentally included.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, will remove

Binary file not shown.
22 changes: 12 additions & 10 deletions HOWTO.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The name clock_id is not specific enough and risks being confused with the option clocksource. How about something like log_clock_id?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Gotcha. It used to be log_alternate_epoch_clock_id. The only problem with log_clock_id is that it now affects the job start time recorded in the json, which is independent of the log_alternate_epoch setting which controls if the log files use times based on this (needs better name) clock_id.

How about alternate_epoch_clock_id, and then I rename the clock_gettime_job_start variable and json entry to alternate_epoch_job_start ? I think that may work pretty well if it sounds ok to you.

Copy link
Collaborator

@vincentkfu vincentkfu Aug 29, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it be cleaner to just create a brand new option and struct thread_data member for job start time? It's just an accident that job start time is related to the issues with the clock used for logging. I bring this up because it seems difficult to find an option name that covers both purposes. How about just calling the new JSON key something like job_start and then adding a new job_start_clock_id option? The description for this option should be in the "Time related parameters" section instead of in the "Measurements and reporting" section.

Copy link
Contributor Author

@aggieNick02 aggieNick02 Aug 29, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm happy to do that (completely separate option and struct thread_data member). I started out planning to do that but then ended up the way I submitted because, well, the options are more related than they seem from the documentation side. (You may already be aware of this, but just in case.) Here's the background.

Before I started using fio, there was a log_unix_epoch option. The docs say it logs Unix timestamps, and this is kindof true. What it actually does is remember the Unix timestamp when the job started (obtained via clock_gettime) and then add the elapsed job time (obtained based on the configured clocksource) to obtain a Unix-format timestamp for each entry. This is actually different than what you'd get by calling clock_gettime to get the Unix timestamp for each I/O operation, since Unix time is not monotonic and is affected by NTP.

Then I added log_alternate_epoch, which is just like log_unix_epoch but lets you use any clock_id instead of CLOCK_REALTIME (used for log_unix_epoch). (Interesting aside - in the case of using CLOCK_MONOTONIC_RAW, it turns out that the job start time plus the elapsed job time can actually be the same as what you'd get calling clock_gettime for each I/O,)

Anyways, that's why job start time ends up so "tied" to the options for log file timestamps. But there is no reason the log file timestamps and the recorded job start time have to share the same clock_id.

If I had a time machine, I'd stop any of the log options from being created, and the log files would always record time elapsed since job started, and a single job_start_time would be the only mechanism for recording time using another clock_id, since that is what is really happening in the implementation. The "alternate" timestamps in the log files are really an illusion, if that makes sense.

But I know that can't happen. Maybe all of this is really just another good argument for what you suggested, as it keeps the (imho) log timestamps and recording job start time completely separate in terms of implementation, so either one could be revamped in the future without having to worry about the other.

Just let me know what you think is best (just make it two separate things or try to come up with an option name for both purposes); I'm happy to do it either way.

Thanks for listening to my rambling thoughts.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the recap. I think it would be cleaner to just have an entirely separate start time feature.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cool, I'll do that then. Thanks for the feedback!


Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's a redundant mention of clock_gettime in the first sentence below.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oops, thanks, I'll fix that.

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

Expand Down
2 changes: 1 addition & 1 deletion backend.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand Down
6 changes: 2 additions & 4 deletions cconv.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down
1 change: 1 addition & 0 deletions client.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
18 changes: 9 additions & 9 deletions fio.1
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion fio.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
2 changes: 1 addition & 1 deletion fio_time.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
2 changes: 1 addition & 1 deletion libfio.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand Down
21 changes: 7 additions & 14 deletions options.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
},
Expand Down
2 changes: 1 addition & 1 deletion rate-submit.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);

Expand Down
6 changes: 5 additions & 1 deletion stat.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand Down Expand Up @@ -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...
Expand Down Expand Up @@ -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);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the following would be easier for a human to read:

s->time = t;
if (iolog->td && iolog->td->o.log_alternate_epoch)
    s->time += iolog->td->clock_gettime_job_start;

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, agreed. I had pulled the boolean out when the test had gotten more complicated but it ended up pretty short. I'll update.

s->bs = bs;
s->priority = priority;
Expand Down
1 change: 1 addition & 0 deletions stat.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
7 changes: 3 additions & 4 deletions thread_options.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down
12 changes: 5 additions & 7 deletions time.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down