Extend import_progress kstat with a notes field #15539

don-brady · 2023-11-17T06:08:56Z

Motivation and Context

As reported and observed in other issues, the time for an unclean pool import can take a long time. It would be nice to be able to observe where the time is being spent for imports that are taking a long time to complete.

Description

This change adds more details to the existing import_progress kstat in the form of import progress notes.

This information is also logged to the zfs debug messages.

Sponsored-By: OpenDrives Inc.
Sponsored-By: Klara Inc.

Here's an example of output from the zfs debug messages:

1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Starting import
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' using uberblock with txg=33
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading checkpoint txg
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading indirect vdev metadata
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Checking feature flags
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading special MOS directories
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading properties
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading AUX vdevs
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading vdev metadata
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 0 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 1 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 2 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 3 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 4 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 5 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 6 of 18 log space maps in 0 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 7 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 8 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 9 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 10 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 11 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 12 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 13 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 14 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 15 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 16 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 17 of 18 log space maps in 1 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' read 18 log space maps (18 total blocks - blksz = 131072 bytes) in 2 ms
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading dedup tables
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Loading BRT
1700151770   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Verifying Log Devices
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Verifying pool data
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Calculating deflated space
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Starting import
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Claiming ZIL blocks
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Syncing ZIL claims
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Updating configs
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Starting resilvers
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Restarting device removals
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Cleaning up inconsistent objsets
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Cleaning up temporary uerrefs
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Restarting Initialize
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Restarting TRIM
1700151771   spa_misc.c:2306:spa_import_progress_set_notes(): 'testpool1' Finished importing

How Has This Been Tested?

Added a new ZTS test, zpool_import_status, to verify the kstat and zfs dbgmsg outputs.
Also ran ztest and performed some manual pool import testing

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.

module/zfs/spa_log_spacemap.c

module/zfs/spa_misc.c

include/sys/spa.h

behlendorf

We should also add some progress notes to spa_activity_check() since with MMP enabled this can take a significant amount of time when the pool hasn't been cleanly exported.

module/zfs/spa.c

don-brady · 2023-11-27T17:11:17Z

Updated to address review feedback

module/zfs/spa.c

module/zfs/spa_log_spacemap.c

module/zfs/spa.c

module/zfs/spa_misc.c

module/zfs/spa.c

don-brady · 2023-11-30T05:42:38Z

Another pass to address Alexander's feedback.

module/zfs/spa_log_spacemap.c

tests/zfs-tests/tests/functional/cli_root/zpool_import/zpool_import_status.ksh

Detail the import progress of log spacemaps as they can take a very long time. Also grab the spa_note() messages to, as they provide insight into what is happening Sponsored-By: OpenDrives Inc. Sponsored-By: Klara Inc. Co-authored-by: Don Brady <[email protected]> Signed-off-by: Don Brady <[email protected]>

don-brady · 2023-11-30T20:21:18Z

Fixed Linux-specific date format

Detail the import progress of log spacemaps as they can take a very long time. Also grab the spa_note() messages to, as they provide insight into what is happening Sponsored-By: OpenDrives Inc. Sponsored-By: Klara Inc. Reviewed-by: Alexander Motin <[email protected]> Reviewed-by: Brian Behlendorf <[email protected]> Signed-off-by: Don Brady <[email protected]> Co-authored-by: Allan Jude <[email protected]> Closes openzfs#15539

Detail the import progress of log spacemaps as they can take a very long time. Also grab the spa_note() messages to, as they provide insight into what is happening Sponsored-By: OpenDrives Inc. Sponsored-By: Klara Inc. Reviewed-by: Alexander Motin <[email protected]> Reviewed-by: Brian Behlendorf <[email protected]> Signed-off-by: Don Brady <[email protected]> Co-authored-by: Allan Jude <[email protected]> Closes #15539

Detail the import progress of log spacemaps as they can take a very long time. Also grab the spa_note() messages to, as they provide insight into what is happening Sponsored-By: OpenDrives Inc. Sponsored-By: Klara Inc. Reviewed-by: Alexander Motin <[email protected]> Reviewed-by: Brian Behlendorf <[email protected]> Signed-off-by: Don Brady <[email protected]> Co-authored-by: Allan Jude <[email protected]> Closes openzfs#15539

amotin reviewed Nov 17, 2023

View reviewed changes

module/zfs/spa_log_spacemap.c Outdated Show resolved Hide resolved

module/zfs/spa_misc.c Outdated Show resolved Hide resolved

include/sys/spa.h Outdated Show resolved Hide resolved

behlendorf reviewed Nov 17, 2023

View reviewed changes

module/zfs/spa.c Outdated Show resolved Hide resolved

behlendorf added the Status: Code Review Needed Ready for review and testing label Nov 17, 2023

don-brady force-pushed the import-status-notes branch from 082ac26 to c39ecc7 Compare November 27, 2023 17:10

behlendorf reviewed Nov 27, 2023

View reviewed changes

module/zfs/spa.c Outdated Show resolved Hide resolved

don-brady force-pushed the import-status-notes branch from c39ecc7 to 517fb73 Compare November 28, 2023 22:39

behlendorf reviewed Nov 28, 2023

View reviewed changes

don-brady force-pushed the import-status-notes branch from 517fb73 to a43cb21 Compare November 29, 2023 01:16

behlendorf approved these changes Nov 29, 2023

View reviewed changes

amotin reviewed Nov 29, 2023

View reviewed changes

module/zfs/spa.c Outdated Show resolved Hide resolved

module/zfs/spa.c Outdated Show resolved Hide resolved

don-brady force-pushed the import-status-notes branch from a43cb21 to 9f58b84 Compare November 30, 2023 05:38

amotin reviewed Nov 30, 2023

View reviewed changes

module/zfs/spa_log_spacemap.c Outdated Show resolved Hide resolved

tests/zfs-tests/tests/functional/cli_root/zpool_import/zpool_import_status.ksh Outdated Show resolved Hide resolved

tests/zfs-tests/tests/functional/cli_root/zpool_import/zpool_import_status.ksh Outdated Show resolved Hide resolved

don-brady force-pushed the import-status-notes branch from 9f58b84 to a64bbab Compare November 30, 2023 18:31

amotin reviewed Nov 30, 2023

View reviewed changes

tests/zfs-tests/tests/functional/cli_root/zpool_import/zpool_import_status.ksh Outdated Show resolved Hide resolved

don-brady force-pushed the import-status-notes branch from a64bbab to 9189ed9 Compare November 30, 2023 20:19

behlendorf approved these changes Dec 1, 2023

View reviewed changes

behlendorf added Status: Accepted Ready to integrate (reviewed, tested) and removed Status: Code Review Needed Ready for review and testing labels Dec 5, 2023

behlendorf merged commit 687e4d7 into openzfs:master Dec 5, 2023
22 of 26 checks passed

robn mentioned this pull request Sep 9, 2024

Add Message(s) Indicating the Progress of An Import #16516

Open

amotin mentioned this pull request Oct 31, 2024

zpool import progress indicator #8646

Closed

12 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Extend import_progress kstat with a notes field #15539

Extend import_progress kstat with a notes field #15539

don-brady commented Nov 17, 2023

behlendorf left a comment

don-brady commented Nov 27, 2023

don-brady commented Nov 30, 2023

don-brady commented Nov 30, 2023

Extend import_progress kstat with a notes field #15539

Extend import_progress kstat with a notes field #15539

Conversation

don-brady commented Nov 17, 2023

Motivation and Context

Description

How Has This Been Tested?

Types of changes

Checklist:

behlendorf left a comment

Choose a reason for hiding this comment

don-brady commented Nov 27, 2023

don-brady commented Nov 30, 2023

don-brady commented Nov 30, 2023