diff --git a/cmd/zpool/zpool_main.c b/cmd/zpool/zpool_main.c index e00fdb7ae1..a13ff5ebdf 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 60c1b84602..65515e3829 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 2939c03665..0482e0f6c3 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 74f05e268c..c64330e289 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); }