From 99dcf32a4f13209d31a717626c50527fe53f7b88 Mon Sep 17 00:00:00 2001 From: aggieNick02 Date: Thu, 24 Aug 2023 11:55:50 -0500 Subject: [PATCH] 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.swp | Bin 0 -> 16384 bytes HOWTO.rst | 22 ++++++++++++---------- backend.c | 2 +- cconv.c | 6 ++---- client.c | 1 + fio.1 | 18 +++++++++--------- fio.h | 2 +- fio_time.h | 2 +- libfio.c | 2 +- options.c | 21 +++++++-------------- rate-submit.c | 2 +- stat.c | 6 +++++- stat.h | 1 + thread_options.h | 7 +++---- time.c | 12 +++++------- 15 files changed, 50 insertions(+), 54 deletions(-) create mode 100644 .HOWTO.rst.swp diff --git a/.HOWTO.rst.swp b/.HOWTO.rst.swp new file mode 100644 index 0000000000000000000000000000000000000000..05a9b375e35676f1183207212973a28ec2d2f8da GIT binary patch literal 16384 zcmeI3e~@HXRmUF$1C1mb6G14Ix&(yXai)7_5;n=On-~*grXaOzX4qf|reF8FJ^eDT z-|M{hdS-f)iWYxZ7U2)8w8}C<6|txyC1pxWqE+A@sQdv&1E^6Vs6YaVB#M$Bf(ZCI z_ntS?{bpxPiYlutdn(_Z?)QE7+{dI>y8T;w@lNad6F04&Xy!$E z*5Na9rh%CTzAp`&7hJNuv?wB8fAQry<iAc^bXxwuD1TD7?DsY0 ztNs0QjsNG`{9ml`Pbgp6Z?Q2g|8eEpI{&ZK_^&EoU12>@#dDl>cCj|B~{R{?2{H^!P6-|5hE}t?~b){Ld?Ye~te~U#9Z!s_}oReC59n)cC)s$u}2G z%YRV$Dn1QsyoTeT+TTMpUY9ldHPgUM12YZGG%(Y^Oan6w{J+;gNW<~tXyGTMU#8}) z`txs4zdi;Y1-}li1K*}*{xIl*i-4=a`TY#F`qSWdKnUi+bMyz#g2%yE!3RJAa?k@7 zEP+LEF?bz#gr4PB!4B94w}BYE9{dP+6?i519=*|b!Kc6{!9CzN!8%w2F9v@^|MiF9 z0q_BEH+T=Y9Sp&bg3rmr$GkZ2CfCK1+NBA(}z9310Mq)2EPQx;HSV6 zxBwgi&r$F`3myb=7jYl>5V!-J2DgBBf-At~;FaKq!6&fuonR5X5s2O20M7o?=#09X zwk(=KqnG7_uxuLBzOBg8pKP1BFiE^={rC2~u{&KmEKOXRFp3Hjn%*c$Of(t{P1ZAI z-;4mBUfF;3XdSzk;A~Qy!Prcv7b6#R*D~Khtnv+s!kJIbOYhgd1$WVNEC5 zEc38y3zMbEc-}-=`liwpWtgMEbZk~zC-%u2$jF6iOXr@hSNR!kd-Hj2?uY++EB zIi00q$t3G;B5f;XuOjDkCpvh%_=(J5b1a+NFp?4ef&YH+Q2s4a7>!XN=80^HOJPYF zK0zEjI>|P~--fv@idJN+k21dceDGjwWyEhyu^pG)KAtG!$4@xf!Nb52++M?+Cy_2l3&13SoaVrRmsa}#-E*}=g>WNEjL>_`adDyxNN~M2VH4LEw~ttjH>zVS2Ic%F7P19~K@DCRWaV|2? zGiSSPw&NrT8fs+B)5!>|5~XF5w#aNtGTRFCI2#qLI5U+t$RpucvRS*0@{uJGQ2fNL zq@EP~%t8gh!Wn*oYb5odizH5WLp!;8Ai1g>MLg??caw1>Hxetu(hRaF?u|`G3}xzK zNJt?a^o+#yvQNI2^VqTda7#?GPNWSx*%p81Y?5ze)wnw;HL^XXkNj4QM5`nVNz-w< zYXljX+c%N#F>K>{W@6c6o=WUy_T21xfhqdgD2dEAVUjQ#k}qUYl~}`4axz|f-H)B0 z7%7^N#TVnW+t0I914R4QsY%6wSO~k>okHv;TiZWLNG2ssF@$I@xk-evg+WM!1y}KT z)z>X@Kx~SmSt)u#S;V|kY9d0YQ}px@5{6};L@x7hhbhHL#(reDWBhX0e%2gbyJl_G z2N@Jz;NVO)l1N3^-54R3-(l3+mQrJ0q;;L<@Gk#WF-%x7M?uyim4Yj2?3PW{2!0K5 zQH-q6SDBk8Wa#-CghR<4PCufDsfl#me%ljz9(CDZSca9FH!>$86VI15^UW=r-(pMI zdl8>@%5AtKikosyB3pFxm@y%FGewEGsV@}dZHX<7)pSC~-To-u+_kOjOQv-@TNfu1 znNFH0kyx@7CL=q~0)E<6AA3un$Wb5U^~f#0GwSv5;b>QnQJiyhT6wtbW?(IYct_^* zJ}u7ZEK^9qitW=f=Ad)%Fq=yw$yhcp#r1Nsi}QC;_2J@(vly1um5V?(MJ2$T$c-BG zT6YZPkUL{?LQAOua7N7QsxDzvF0m3@i&U4!_spW!a6t@LuOIf6pt4ESG&nv>>#$!c zH%a=TJAQr>*-#3-PF9xLfLKsU`64IAFR+)9dbZh0z=16Y6d;pY_2) zORCD*WGIRXs@TMs7VpdK1?9d|FWMnNCvHpF)rC({t^^;qObGyHZX?M$A=!TSvFgrG zK`55sE4f}%x4C*xf|y1%=IVSckg}eO$i0|<4o??grL-nQl+G(8(MWL}6aS^m3}sJv zsq@+0;D#{>r|L+=@(0Oa6y@OH2cE&zwX6Wj$n4t@*V15Sby;1D<;e4M_21P+5|=%r0h|Y30iL3de-ivD_!Cfo zli&n62Yi(Ny$@as9->EoKX@M~!P~%F!FSM)=;(JvPqUwy24)(VY2bfd1KW~2C3q9y zNuiP&xaUZtg)otJ4OdlbB@JDr`>f zb<$iXWN0U-j7*Wl8+}?YL2~x;`3pxrPfGtpTIcULpT`S8M5t<>t~+{?D?- z=F;*~Q?h29HOs;9Z0{{jz86f3n3v4#w=eyf=~9-E1Gzo%xqD?L(0uCBFOU0KQOadp zK{M80q8F3$fRD?r#iK-DJt+;0T=nqI)NG6LZcrsrS-c1`EAnZjy|)=I5xMH=lZjXK z%8-82>#=RxvH*Fv9aIu1%dW!&b|)Ng)kvo9Rrd51y%ZU~?v(ajr<>HP-vo`W$foja zvzUysMdxgrl>AOxHMA*xmx$Zjq*T}PL=8+O!M9+QyPQ12zI;#Uh4x9r(+V06DL1s_ zlHC+svDtz51=o(ct5Yu;@3dVT(^I<#4V03&0BH_8IR9 z8Zvab$&&JB#LXBtLDaMU@zTD>foP#B;l$;Z_Z$vsXYdE_A$1p!##s&$m*DCamECuD z(hjg3H|ezrg~z-_%R71K?Y*lo-~G6*-PyV4lr3#PeF4pRWvjzF?TT4iTr{U{C|Y`s z2oLlpY9TdGC~ZeyCgd+nh&kHOpa>T{+`Jqc!PP^^y(XL)tuDw9bE%ls1zEnD~)rAdBRyKNK&$VacVLmPukAL3p$7g zd>Rd0<0c8uP3GLw`1e^BYap&kA4v?=4G{svhR61#UAa&FXn$gf`)qL{?YcPW4LvzY zXfF0g=BD%Jb9TCU0%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)); diff --git a/cconv.c b/cconv.c index ce6acbe6ab..84e408aa04 100644 --- a/cconv.c +++ b/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); diff --git a/client.c b/client.c index c257036bf5..be2cdbf139 100644 --- 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->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); diff --git a/fio.1 b/fio.1 index f0dc49ab00..c5c0c29ceb 100644 --- a/fio.1 +++ b/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 diff --git a/fio.h b/fio.h index a54f57c93e..2783580d2e 100644 --- a/fio.h +++ b/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; diff --git a/fio_time.h b/fio_time.h index 62d92120a5..7b9c3c3ce3 100644 --- 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); #endif diff --git a/libfio.c b/libfio.c index 5e3fd30b71..0e0bc3ed53 100644 --- a/libfio.c +++ b/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)); diff --git a/options.c b/options.c index 48aa0d7b1c..9eb9cb2f57 100644 --- a/options.c +++ b/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, }, diff --git a/rate-submit.c b/rate-submit.c index 6f6d15bd66..07552e8571 100644 --- 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.clock_id); fio_getrusage(&td->ru_start); clear_io_state(td, 1); diff --git a/stat.c b/stat.c index 7b791628f4..234129a7f4 100644 --- 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, "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; diff --git a/stat.h b/stat.h index 8ceabc48c7..a0f717c464 100644 --- 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 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; diff --git a/thread_options.h b/thread_options.h index 38a9993d23..0e32b2171d 100644 --- a/thread_options.h +++ b/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; diff --git a/time.c b/time.c index 5c4d6de039..a4a9fee2e2 100644 --- a/time.c +++ b/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)