c/mirror_zfs
1
0
Fork 0
mirror of https://git.proxmox.com/git/mirror_zfs.git synced 2024-11-17 10:01:01 +03:00
Code Issues Packages Projects Releases Wiki Activity

record ioctl elapsed time in zpool history

Browse Source 
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 <mmaybee@cray.com>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: Matthew Ahrens <mahrens@delphix.com>
Closes #11440
This commit is contained in:
Matthew Ahrens 2021-01-11 09:29:25 -08:00 committed by GitHub
parent dc303dcf5b
commit 2ac90457f5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 20 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
cmd/zpool/zpool_main.c
View File

@ -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));

1
include/sys/fs/zfs.h
View File

@ -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

8
module/zfs/spa_history.c
View File

@ -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);

3
module/zfs/zfs_ioctl.c
View File

@ -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);
}