From 2ac90457f503e84a3acf8b7c368cd8e44677f7d3 Mon Sep 17 00:00:00 2001 From: Matthew Ahrens Date: Mon, 11 Jan 2021 09:29:25 -0800 Subject: [PATCH] record ioctl elapsed time in zpool history Each zfs ioctl that changes on-disk state (e.g. set property, create snapshot, destroy filesystem) is recorded in the zpool history, and is printed by `zpool history -i`. For performance diagnostic purposes, it would be useful to know how long each of these ioctls took to run. This commit adds that functionality, with a new `ZPOOL_HIST_ELAPSED_NS` member of the history nvlist. Additionally, the time recorded in this history log is currently the time that the history record is written to disk. But in many cases (CLI args logging and ioctl logging), this happens asynchronously, potentially many seconds after the operation completed. This commit changes the timestamp to reflect when the history event was created, rather than when it was written to disk. Reviewed-by: Mark Maybee Reviewed-by: Brian Behlendorf Signed-off-by: Matthew Ahrens Closes #11440 --- cmd/zpool/zpool_main.c | 10 +++++++++- include/sys/fs/zfs.h | 1 + module/zfs/spa_history.c | 8 +++++++- module/zfs/zfs_ioctl.c | 3 +++ 4 files changed, 20 insertions(+), 2 deletions(-) diff --git a/cmd/zpool/zpool_main.c b/cmd/zpool/zpool_main.c index e00fdb7ae..a13ff5ebd 100644 --- a/cmd/zpool/zpool_main.c +++ b/cmd/zpool/zpool_main.c @@ -9063,7 +9063,7 @@ print_history_records(nvlist_t *nvhis, hist_cbdata_t *cb) &records, &numrecords) == 0); for (i = 0; i < numrecords; i++) { nvlist_t *rec = records[i]; - char tbuf[30] = ""; + char tbuf[64] = ""; if (nvlist_exists(rec, ZPOOL_HIST_TIME)) { time_t tsec; @@ -9075,6 +9075,14 @@ print_history_records(nvlist_t *nvhis, hist_cbdata_t *cb) (void) strftime(tbuf, sizeof (tbuf), "%F.%T", &t); } + if (nvlist_exists(rec, ZPOOL_HIST_ELAPSED_NS)) { + uint64_t elapsed_ns = fnvlist_lookup_int64(records[i], + ZPOOL_HIST_ELAPSED_NS); + (void) snprintf(tbuf + strlen(tbuf), + sizeof (tbuf) - strlen(tbuf), + " (%lldms)", (long long)elapsed_ns / 1000 / 1000); + } + if (nvlist_exists(rec, ZPOOL_HIST_CMD)) { (void) printf("%s %s", tbuf, fnvlist_lookup_string(rec, ZPOOL_HIST_CMD)); diff --git a/include/sys/fs/zfs.h b/include/sys/fs/zfs.h index 60c1b8460..65515e382 100644 --- a/include/sys/fs/zfs.h +++ b/include/sys/fs/zfs.h @@ -1456,6 +1456,7 @@ typedef enum { #define ZPOOL_HIST_DSNAME "dsname" #define ZPOOL_HIST_DSID "dsid" #define ZPOOL_HIST_ERRNO "errno" +#define ZPOOL_HIST_ELAPSED_NS "elapsed_ns" /* * Special nvlist name that will not have its args recorded in the pool's diff --git a/module/zfs/spa_history.c b/module/zfs/spa_history.c index 2939c0366..0482e0f6c 100644 --- a/module/zfs/spa_history.c +++ b/module/zfs/spa_history.c @@ -288,7 +288,6 @@ spa_history_log_sync(void *arg, dmu_tx_t *tx) } #endif - fnvlist_add_uint64(nvl, ZPOOL_HIST_TIME, gethrestime_sec()); fnvlist_add_string(nvl, ZPOOL_HIST_HOST, utsname()->nodename); if (nvlist_exists(nvl, ZPOOL_HIST_CMD)) { @@ -396,6 +395,12 @@ spa_history_log_nvl(spa_t *spa, nvlist_t *nvl) } fnvlist_add_uint64(nvarg, ZPOOL_HIST_WHO, crgetruid(CRED())); + /* + * Since the history is recorded asynchronously, the effective time is + * now, which may be considerably before the change is made on disk. + */ + fnvlist_add_uint64(nvarg, ZPOOL_HIST_TIME, gethrestime_sec()); + /* Kick this off asynchronously; errors are ignored. */ dsl_sync_task_nowait(spa_get_dsl(spa), spa_history_log_sync, nvarg, tx); dmu_tx_commit(tx); @@ -526,6 +531,7 @@ log_internal(nvlist_t *nvl, const char *operation, spa_t *spa, fnvlist_add_string(nvl, ZPOOL_HIST_INT_NAME, operation); fnvlist_add_uint64(nvl, ZPOOL_HIST_TXG, tx->tx_txg); + fnvlist_add_uint64(nvl, ZPOOL_HIST_TIME, gethrestime_sec()); if (dmu_tx_is_syncing(tx)) { spa_history_log_sync(nvl, tx); diff --git a/module/zfs/zfs_ioctl.c b/module/zfs/zfs_ioctl.c index 74f05e268..c64330e28 100644 --- a/module/zfs/zfs_ioctl.c +++ b/module/zfs/zfs_ioctl.c @@ -7416,6 +7416,7 @@ zfsdev_ioctl_common(uint_t vecnum, zfs_cmd_t *zc, int flag) size_t saved_poolname_len = 0; nvlist_t *innvl = NULL; fstrans_cookie_t cookie; + hrtime_t start_time = gethrtime(); cmd = vecnum; error = 0; @@ -7574,6 +7575,8 @@ zfsdev_ioctl_common(uint_t vecnum, zfs_cmd_t *zc, int flag) fnvlist_add_int64(lognv, ZPOOL_HIST_ERRNO, error); } + fnvlist_add_int64(lognv, ZPOOL_HIST_ELAPSED_NS, + gethrtime() - start_time); (void) spa_history_log_nvl(spa, lognv); spa_close(spa, FTAG); }