From 9a4f91abc07e77165baa7f0499a4887ec9f3e4fe Mon Sep 17 00:00:00 2001 From: Csaba Henk Date: Thu, 12 Mar 2020 08:20:31 +0100 Subject: Indicate timezone offsets in timestamps Logs and other output carrying timestamps will have now timezone offsets indicated, eg.: [2020-03-12 07:01:05.584482 +0000] I [MSGID: 106143] [glusterd-pmap.c:388:pmap_registry_remove] 0-pmap: removing brick (null) on port 49153 To this end, - gf_time_fmt() now inserts timezone offset via %z strftime(3) template. - A new utility function has been added, gf_time_fmt_tv(), that takes a struct timeval pointer (*tv) instead of a time_t value to specify the time. If tv->tv_usec is negative, gf_time_fmt_tv(... tv ...) is equivalent to gf_time_fmt(... tv->tv_sec ...) Otherwise it also inserts tv->tv_usec to the formatted string. - Building timestamps of usec precision has been converted to gf_time_fmt_tv, which is necessary because the method of appending a period and the usec value to the end of the timestamp does not work if the timestamp has zone offset, but it's also beneficial in terms of eliminating repetition. - The buffer passed to gf_time_fmt/gf_time_fmt_tv has been unified to be of GF_TIMESTR_SIZE size (256). We need slightly larger buffer space to accommodate the zone offset and it's preferable to use a buffer which is undisputedly large enough. This change does *not* do the following: - Retaining a method of timestamp creation without timezone offset. As to my understanding we don't need such backward compatibility as the code just emits timestamps to logs and other diagnostic texts, and doesn't do any later processing on them that would rely on their format. An exception to this, ie. a case where timestamp is built for internal use, is graph.c:fill_uuid(). As far as I can see, what matters in that case is the uniqueness of the produced string, not the format. - Implementing a single-token (space free) timestamp format. While some timestamp formats used to be single-token, now all of them will include a space preceding the offset indicator. Again, I did not see a use case where this could be significant in terms of representation. - Moving the codebase to a single unified timestamp format and dropping the fmt argument of gf_time_fmt/gf_time_fmt_tv. While the gf_timefmt_FT format is almost ubiquitous, there are a few cases where different formats are used. I'm not convinced there is any reason to not use gf_timefmt_FT in those cases too, but I did not want to make a decision in this regard. Change-Id: I0af73ab5d490cca7ed8d07a2ce7ac22a6df2920a Updates: #837 Signed-off-by: Csaba Henk --- xlators/debug/io-stats/src/io-stats.c | 36 +++++++---------------- xlators/debug/trace/src/trace.c | 20 ++++++------- xlators/features/bit-rot/src/bitd/bit-rot-scrub.c | 12 ++++---- xlators/features/locks/src/posix.c | 8 ++--- xlators/features/trash/src/trash.c | 2 +- xlators/mgmt/glusterd/src/glusterd-handler.c | 2 +- xlators/mgmt/glusterd/src/glusterd-snapshot.c | 2 +- xlators/mgmt/glusterd/src/glusterd-utils.c | 2 +- xlators/mount/fuse/src/fuse-bridge.c | 6 ++-- xlators/performance/io-cache/src/io-cache.c | 8 ++--- xlators/performance/quick-read/src/quick-read.c | 7 ++--- xlators/storage/posix/src/posix-helpers.c | 2 +- 12 files changed, 42 insertions(+), 65 deletions(-) (limited to 'xlators') diff --git a/xlators/debug/io-stats/src/io-stats.c b/xlators/debug/io-stats/src/io-stats.c index 4e1f6e5af07..345dbe7e09c 100644 --- a/xlators/debug/io-stats/src/io-stats.c +++ b/xlators/debug/io-stats/src/io-stats.c @@ -678,10 +678,7 @@ ios_dump_throughput_stats(struct ios_stat_head *list_head, xlator_t *this, FILE *logfp, ios_stats_thru_t type) { struct ios_stat_list *entry = NULL; - struct timeval time = { - 0, - }; - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; @@ -689,12 +686,9 @@ ios_dump_throughput_stats(struct ios_stat_head *list_head, xlator_t *this, { list_for_each_entry(entry, &list_head->iosstats->list, list) { - gf_time_fmt(timestr, sizeof timestr, - entry->iosstat->thru_counters[type].time.tv_sec, - gf_timefmt_FT); - snprintf(timestr + strlen(timestr), - sizeof timestr - strlen(timestr), ".%" GF_PRI_SUSECONDS, - time.tv_usec); + gf_time_fmt_tv(timestr, sizeof timestr, + &entry->iosstat->thru_counters[type].time, + gf_timefmt_FT); ios_log(this, logfp, "%s \t %-10.2f \t %s", timestr, entry->value, entry->iosstat->filename); @@ -1216,7 +1210,7 @@ io_stats_dump_global_to_logfp(xlator_t *this, struct ios_global_stats *stats, int index = 0; struct ios_stat_head *list_head = NULL; struct ios_conf *conf = NULL; - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; char str_header[128] = {0}; @@ -1325,11 +1319,8 @@ io_stats_dump_global_to_logfp(xlator_t *this, struct ios_global_stats *stats, if (interval == -1) { LOCK(&conf->lock); { - gf_time_fmt(timestr, sizeof timestr, - conf->cumulative.max_openfd_time.tv_sec, gf_timefmt_FT); - snprintf(timestr + strlen(timestr), - sizeof timestr - strlen(timestr), ".%" GF_PRI_SUSECONDS, - conf->cumulative.max_openfd_time.tv_usec); + gf_time_fmt_tv(timestr, sizeof timestr, + &conf->cumulative.max_openfd_time, gf_timefmt_FT); ios_log(this, logfp, "Current open fd's: %" PRId64 " Max open fd's: %" PRId64 " time %s", @@ -1808,7 +1799,7 @@ io_stats_dump_stats_to_dict(xlator_t *this, dict_t *resp, struct ios_stat_list *entry = NULL; int ret = -1; ios_stats_thru_t index = IOS_STATS_THRU_MAX; - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; char *dict_timestr = NULL; @@ -1827,14 +1818,9 @@ io_stats_dump_stats_to_dict(xlator_t *this, dict_t *resp, ret = dict_set_uint64(resp, "max-open", conf->cumulative.max_nr_opens); - gf_time_fmt(timestr, sizeof timestr, - conf->cumulative.max_openfd_time.tv_sec, - gf_timefmt_FT); - if (conf->cumulative.max_openfd_time.tv_sec) - snprintf(timestr + strlen(timestr), - sizeof timestr - strlen(timestr), - ".%" GF_PRI_SUSECONDS, - conf->cumulative.max_openfd_time.tv_usec); + gf_time_fmt_tv(timestr, sizeof timestr, + &conf->cumulative.max_openfd_time, + gf_timefmt_FT); dict_timestr = gf_strdup(timestr); if (!dict_timestr) diff --git a/xlators/debug/trace/src/trace.c b/xlators/debug/trace/src/trace.c index 3db2e263524..6ed0ca00342 100644 --- a/xlators/debug/trace/src/trace.c +++ b/xlators/debug/trace/src/trace.c @@ -22,13 +22,13 @@ static void trace_stat_to_str(struct iatt *buf, char *str, size_t len) { - char atime_buf[200] = { + char atime_buf[GF_TIMESTR_SIZE] = { 0, }; - char mtime_buf[200] = { + char mtime_buf[GF_TIMESTR_SIZE] = { 0, }; - char ctime_buf[200] = { + char ctime_buf[GF_TIMESTR_SIZE] = { 0, }; @@ -64,7 +64,7 @@ trace_stat_to_str(struct iatt *buf, char *str, size_t len) int dump_history_trace(circular_buffer_t *cb, void *data) { - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; @@ -72,9 +72,7 @@ dump_history_trace(circular_buffer_t *cb, void *data) gettimeofday () fails, it's safe to check tm and then dump the time at which the entry was added to the buffer */ - gf_time_fmt(timestr, sizeof timestr, cb->tv.tv_sec, gf_timefmt_Ymd_T); - snprintf(timestr + strlen(timestr), 256 - strlen(timestr), - ".%" GF_PRI_SUSECONDS, cb->tv.tv_usec); + gf_time_fmt_tv(timestr, sizeof timestr, &cb->tv, gf_timefmt_Ymd_T); gf_proc_dump_write("TIME", "%s", timestr); gf_proc_dump_write("FOP", "%s\n", (char *)cb->data); @@ -2209,10 +2207,10 @@ int trace_setattr(call_frame_t *frame, xlator_t *this, loc_t *loc, struct iatt *stbuf, int32_t valid, dict_t *xdata) { - char actime_str[256] = { + char actime_str[GF_TIMESTR_SIZE] = { 0, }; - char modtime_str[256] = { + char modtime_str[GF_TIMESTR_SIZE] = { 0, }; trace_conf_t *conf = NULL; @@ -2278,10 +2276,10 @@ int trace_fsetattr(call_frame_t *frame, xlator_t *this, fd_t *fd, struct iatt *stbuf, int32_t valid, dict_t *xdata) { - char actime_str[256] = { + char actime_str[GF_TIMESTR_SIZE] = { 0, }; - char modtime_str[256] = { + char modtime_str[GF_TIMESTR_SIZE] = { 0, }; trace_conf_t *conf = NULL; diff --git a/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c b/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c index 10c0478f2e8..c4607654365 100644 --- a/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c +++ b/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c @@ -601,7 +601,7 @@ br_fsscan_deactivate(xlator_t *this) static void br_scrubber_log_time(xlator_t *this, const char *sfx) { - char timestr[1024] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct timeval tv = { @@ -628,7 +628,7 @@ br_scrubber_log_time(xlator_t *this, const char *sfx) static void br_fsscanner_log_time(xlator_t *this, br_child_t *child, const char *sfx) { - char timestr[1024] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct timeval tv = { @@ -922,7 +922,7 @@ br_fsscan_schedule(xlator_t *this) struct timeval tv = { 0, }; - char timestr[1024] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct br_scrubber *fsscrub = NULL; @@ -975,7 +975,7 @@ int32_t br_fsscan_activate(xlator_t *this) { uint32_t timo = 0; - char timestr[1024] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct timeval now = { @@ -1020,7 +1020,7 @@ br_fsscan_reschedule(xlator_t *this) { int32_t ret = 0; uint32_t timo = 0; - char timestr[1024] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct timeval now = { @@ -1073,7 +1073,7 @@ br_fsscan_ondemand(xlator_t *this) { int32_t ret = 0; uint32_t timo = 0; - char timestr[1024] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct timeval now = { diff --git a/xlators/features/locks/src/posix.c b/xlators/features/locks/src/posix.c index 8b57627addf..6a712848f9e 100644 --- a/xlators/features/locks/src/posix.c +++ b/xlators/features/locks/src/posix.c @@ -3502,10 +3502,10 @@ pl_dump_lock(char *str, int size, struct gf_flock *flock, gf_lkowner_t *owner, time_t *blkd_time, gf_boolean_t active) { char *type_str = NULL; - char granted[256] = { + char granted[GF_TIMESTR_SIZE] = { 0, }; - char blocked[256] = { + char blocked[GF_TIMESTR_SIZE] = { 0, }; @@ -3556,10 +3556,10 @@ __dump_entrylks(pl_inode_t *pl_inode) { pl_dom_list_t *dom = NULL; pl_entry_lock_t *lock = NULL; - char blocked[256] = { + char blocked[GF_TIMESTR_SIZE] = { 0, }; - char granted[256] = { + char granted[GF_TIMESTR_SIZE] = { 0, }; int count = 0; diff --git a/xlators/features/trash/src/trash.c b/xlators/features/trash/src/trash.c index f44b11c6872..a28aa1e09e0 100644 --- a/xlators/features/trash/src/trash.c +++ b/xlators/features/trash/src/trash.c @@ -212,7 +212,7 @@ void append_time_stamp(char *name, size_t name_size) { int i; - char timestr[64] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; diff --git a/xlators/mgmt/glusterd/src/glusterd-handler.c b/xlators/mgmt/glusterd/src/glusterd-handler.c index 6e6593e7263..96a2f01e0d9 100644 --- a/xlators/mgmt/glusterd/src/glusterd-handler.c +++ b/xlators/mgmt/glusterd/src/glusterd-handler.c @@ -5146,7 +5146,7 @@ glusterd_print_snapinfo_by_vol(FILE *fp, glusterd_volinfo_t *volinfo, glusterd_volinfo_t *tmp_vol = NULL; glusterd_snap_t *snapinfo = NULL; int snapcount = 0; - char timestr[64] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; char snap_status_str[STATUS_STRLEN] = { diff --git a/xlators/mgmt/glusterd/src/glusterd-snapshot.c b/xlators/mgmt/glusterd/src/glusterd-snapshot.c index 6294951afcc..c7f147b7072 100644 --- a/xlators/mgmt/glusterd/src/glusterd-snapshot.c +++ b/xlators/mgmt/glusterd/src/glusterd-snapshot.c @@ -3221,7 +3221,7 @@ glusterd_snapshot_get_snap_detail(dict_t *dict, glusterd_snap_t *snap, int volcount = 0; char key[32] = ""; /* keyprefix is quite small, up to 16 bytes */ int keylen; - char timestr[64] = ""; + char timestr[GF_TIMESTR_SIZE] = ""; char *value = NULL; glusterd_volinfo_t *snap_vol = NULL; glusterd_volinfo_t *tmp_vol = NULL; diff --git a/xlators/mgmt/glusterd/src/glusterd-utils.c b/xlators/mgmt/glusterd/src/glusterd-utils.c index a0b436d2eb8..98e45067dfe 100644 --- a/xlators/mgmt/glusterd/src/glusterd-utils.c +++ b/xlators/mgmt/glusterd/src/glusterd-utils.c @@ -8075,7 +8075,7 @@ glusterd_sm_tr_log_transition_add_to_dict(dict_t *dict, int ret = -1; char key[64] = ""; int keylen; - char timestr[64] = ""; + char timestr[GF_TIMESTR_SIZE] = ""; char *str = NULL; GF_ASSERT(dict); diff --git a/xlators/mount/fuse/src/fuse-bridge.c b/xlators/mount/fuse/src/fuse-bridge.c index 041caf541f0..f198b8f1b11 100644 --- a/xlators/mount/fuse/src/fuse-bridge.c +++ b/xlators/mount/fuse/src/fuse-bridge.c @@ -6332,14 +6332,12 @@ out: int dump_history_fuse(circular_buffer_t *cb, void *data) { - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; - gf_time_fmt(timestr, sizeof timestr, cb->tv.tv_sec, gf_timefmt_F_HMS); + gf_time_fmt_tv(timestr, sizeof timestr, &cb->tv, gf_timefmt_F_HMS); - snprintf(timestr + strlen(timestr), 256 - strlen(timestr), - ".%" GF_PRI_SUSECONDS, cb->tv.tv_usec); gf_proc_dump_write("TIME", "%s", timestr); gf_proc_dump_write("message", "%s\n", (char *)cb->data); diff --git a/xlators/performance/io-cache/src/io-cache.c b/xlators/performance/io-cache/src/io-cache.c index c007e0a355d..2fefaef8de8 100644 --- a/xlators/performance/io-cache/src/io-cache.c +++ b/xlators/performance/io-cache/src/io-cache.c @@ -1945,7 +1945,7 @@ __ioc_cache_dump(ioc_inode_t *ioc_inode, char *prefix) char key[GF_DUMP_MAX_BUF_LEN] = { 0, }; - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; @@ -1956,10 +1956,8 @@ __ioc_cache_dump(ioc_inode_t *ioc_inode, char *prefix) table = ioc_inode->table; if (ioc_inode->cache.tv.tv_sec) { - gf_time_fmt(timestr, sizeof timestr, ioc_inode->cache.tv.tv_sec, - gf_timefmt_FT); - snprintf(timestr + strlen(timestr), sizeof timestr - strlen(timestr), - ".%" GF_PRI_SUSECONDS, ioc_inode->cache.tv.tv_usec); + gf_time_fmt_tv(timestr, sizeof timestr, &ioc_inode->cache.tv, + gf_timefmt_FT); gf_proc_dump_write("last-cache-validation-time", "%s", timestr); } diff --git a/xlators/performance/quick-read/src/quick-read.c b/xlators/performance/quick-read/src/quick-read.c index 4f16d148262..640c9ac51c6 100644 --- a/xlators/performance/quick-read/src/quick-read.c +++ b/xlators/performance/quick-read/src/quick-read.c @@ -1034,7 +1034,7 @@ qr_inodectx_dump(xlator_t *this, inode_t *inode) char key_prefix[GF_DUMP_MAX_BUF_LEN] = { 0, }; - char buf[256] = { + char buf[GF_TIMESTR_SIZE] = { 0, }; @@ -1050,10 +1050,7 @@ qr_inodectx_dump(xlator_t *this, inode_t *inode) qr_inode->data ? "yes" : "no"); if (qr_inode->last_refresh.tv_sec) { - gf_time_fmt(buf, sizeof buf, qr_inode->last_refresh.tv_sec, - gf_timefmt_FT); - snprintf(buf + strlen(buf), sizeof buf - strlen(buf), - ".%" GF_PRI_SUSECONDS, qr_inode->last_refresh.tv_usec); + gf_time_fmt_tv(buf, sizeof buf, &qr_inode->last_refresh, gf_timefmt_FT); gf_proc_dump_write("last-cache-validation-time", "%s", buf); } diff --git a/xlators/storage/posix/src/posix-helpers.c b/xlators/storage/posix/src/posix-helpers.c index 24466c4abf6..73443a6a2e5 100644 --- a/xlators/storage/posix/src/posix-helpers.c +++ b/xlators/storage/posix/src/posix-helpers.c @@ -1924,7 +1924,7 @@ posix_fs_health_check(xlator_t *this, char *file_path) { struct posix_private *priv = NULL; int ret = -1; - char timestamp[256] = { + char timestamp[GF_TIMESTR_SIZE] = { 0, }; int fd = -1; -- cgit