record ioctl elapsed time in zpool history

[ahrens]

Motivation and Context

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.

Description

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.

Note: it would be nice to also record the elapsed time of CLI commands and the sync tasks themselves. However, both of these are much less trivial than the ioctl elapsed time. So I'm leaving those for future work.

Note: since CLI commands elapsed times is not currently recorded, this change only impacts zpool history -i (internal events).

How Has This Been Tested?

example zpool history -i output.

2021-01-07.20:11:21 [txg:26930] create test/fs/a (134)
2021-01-07.20:11:26 (4834ms) ioctl create
    input:
        type: 2
        props:

2021-01-07.20:11:26 zfs create test/fs/a
2021-01-07.20:12:16 [txg:26943] snapshot test/fs@snap (140)
2021-01-07.20:12:16 (53ms) ioctl snapshot
    input:
        snaps:
            test/fs@snap
        props:

2021-01-07.20:12:16 zfs snapshot test/fs@snap
2021-01-07.20:12:21 [txg:26945] destroy test/fs@snap (140)
2021-01-07.20:12:21 (54ms) ioctl destroy_snaps
    input:
        snaps:
            test/fs@snap

2021-01-07.20:12:21 zfs destroy test/fs@snap

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Performance enhancement (non-breaking change which improves efficiency)
• Code cleanup (non-breaking change which makes code smaller or more readable)
• Breaking change (fix or feature that would cause existing functionality to change)
• Library ABI change (libzfs, libzfs_core, libnvpair, libuutil and libzfsbootenv)
• Documentation (a change to man pages or other documentation)

Checklist:

• My code follows the OpenZFS code style requirements.
• I have updated the documentation accordingly.
• I have read the contributing document.
• I have added tests to cover my changes.
• I have run the ZFS Test Suite with this change applied.
• All commit messages are properly formatted and contain Signed-off-by.

[mmaybee]

The changes look good, but is there any concern that this could break any "parsers" out there that are consuming the zpool history output? Although the history output is not considered a "stable" interface, I'm sure there is somebody out there who is feeding it into some home-grown tools.

[ahrens]

@mmaybee I think that we should allow ourselves to change the format of the zpoool history output. Programmatic consumers would probably be better served by using the "spa event" framework, which provides the nvlist itself. See spa_history_log_notify(). If that isn't suitable (e.g. they need to post-process the history rather than just seeing events as they happen), then I think it's reasonable to ask consumers to change.

That said, this commit doesn't change the output of zpool history (without the -i flag). The internal flag should be a good hint that this not not intended for public consumption :-) We've changed the internal history format in the past (to add the nvlist output), and it's generally subject to change as we add/remove kinds of internal events or change the exact message used to log an event.

But I would like to know of any programmatic consumers of the zpool history output so that we can at least notify them about this change!

[mmaybee]

Yup, I agree that we should be able to evolve the output from zpool history. But it would be nice to give a heads up to those who might be trying to consume it programmatically.