Skip to content

Commit

Permalink
Extend import_progress kstat with a notes field
Browse files Browse the repository at this point in the history 
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]>
  • Loading branch information
@allanjude @don-brady
allanjude and don-brady committed Nov 28, 2023
1 parent a94860a commit 517fb73
Show file tree
Hide file tree
Showing 6 changed files with 249 additions and 5 deletions.
3 changes: 3 additions & 0 deletions include/sys/spa.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -971,6 +971,9 @@ extern int spa_import_progress_set_max_txg(uint64_t pool_guid,
uint64_t max_txg);
extern int spa_import_progress_set_state(uint64_t pool_guid,
spa_load_state_t spa_load_state);
extern void spa_import_progress_set_notes(spa_t *spa, const char *notes);
extern void spa_import_progress_set_notes_nolog(spa_t *spa,
const char *notes);

/* Pool configuration locks */
extern int spa_config_tryenter(spa_t *spa, int locks, const void *tag,
Expand Down
41 changes: 41 additions & 0 deletions module/zfs/spa.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3109,6 +3109,7 @@ spa_load(spa_t *spa, spa_load_state_t state, spa_import_type_t type)
spa->spa_load_state = state;
(void) spa_import_progress_set_state(spa_guid(spa),
spa_load_state(spa));
spa_import_progress_set_notes(spa, "spa_load()");

gethrestime(&spa->spa_loaded_ts);
error = spa_load_impl(spa, type, &ereport);
Expand Down Expand Up @@ -3375,6 +3376,12 @@ spa_activity_check(spa_t *spa, uberblock_t *ub, nvlist_t *config)

import_expire = gethrtime() + import_delay;

char buf[128];
(void) snprintf(buf, sizeof (buf), "checking MMP activity, waiting "
"%llu ms", (u_longlong_t)(import_delay/1000000));
spa_import_progress_set_notes(spa, buf);

int interations = 0;
while (gethrtime() < import_expire) {
(void) spa_import_progress_set_mmp_check(spa_guid(spa),
NSEC2SEC(import_expire - gethrtime()));
Expand Down Expand Up @@ -3408,6 +3415,14 @@ spa_activity_check(spa_t *spa, uberblock_t *ub, nvlist_t *config)
break;
}
error = 0;

if (interations++ % 30 == 0 && import_expire > gethrtime()) {
(void) snprintf(buf, sizeof (buf), "checking MMP "
"activity, %llu ms remaining",
(u_longlong_t)
((import_expire - gethrtime())/1000000));
spa_import_progress_set_notes(spa, buf);
}
}

out:
Expand Down Expand Up @@ -4995,6 +5010,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
/*
* Retrieve the checkpoint txg if the pool has a checkpoint.
*/
spa_import_progress_set_notes(spa, "Loading checkpoint txg");
error = spa_ld_read_checkpoint_txg(spa);
if (error != 0)
return (error);
Expand All @@ -5007,6 +5023,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* initiated. Otherwise we could be reading from indirect vdevs before
* we have loaded their mappings.
*/
spa_import_progress_set_notes(spa, "Loading indirect vdev metadata");
error = spa_ld_open_indirect_vdev_metadata(spa);
if (error != 0)
return (error);
Expand All @@ -5015,6 +5032,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* Retrieve the full list of active features from the MOS and check if
* they are all supported.
*/
spa_import_progress_set_notes(spa, "Checking feature flags");
error = spa_ld_check_features(spa, &missing_feat_write);
if (error != 0)
return (error);
Expand All @@ -5023,13 +5041,15 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* Load several special directories from the MOS needed by the dsl_pool
* layer.
*/
spa_import_progress_set_notes(spa, "Loading special MOS directories");
error = spa_ld_load_special_directories(spa);
if (error != 0)
return (error);

/*
* Retrieve pool properties from the MOS.
*/
spa_import_progress_set_notes(spa, "Loading properties");
error = spa_ld_get_props(spa);
if (error != 0)
return (error);
Expand All @@ -5038,6 +5058,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* Retrieve the list of auxiliary devices - cache devices and spares -
* and open them.
*/
spa_import_progress_set_notes(spa, "Loading AUX vdevs");
error = spa_ld_open_aux_vdevs(spa, type);
if (error != 0)
return (error);
Expand All @@ -5046,14 +5067,17 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* Load the metadata for all vdevs. Also check if unopenable devices
* should be autoreplaced.
*/
spa_import_progress_set_notes(spa, "Loading vdev metadata");
error = spa_ld_load_vdev_metadata(spa);
if (error != 0)
return (error);

spa_import_progress_set_notes(spa, "Loading dedup tables");
error = spa_ld_load_dedup_tables(spa);
if (error != 0)
return (error);

spa_import_progress_set_notes(spa, "Loading BRT");
error = spa_ld_load_brt(spa);
if (error != 0)
return (error);
Expand All @@ -5062,6 +5086,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* Verify the logs now to make sure we don't have any unexpected errors
* when we claim log blocks later.
*/
spa_import_progress_set_notes(spa, "Verifying Log Devices");
error = spa_ld_verify_logs(spa, type, ereport);
if (error != 0)
return (error);
Expand All @@ -5083,6 +5108,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* state. When performing an extreme rewind, we verify the whole pool,
* which can take a very long time.
*/
spa_import_progress_set_notes(spa, "Verifying pool data");
error = spa_ld_verify_pool_data(spa);
if (error != 0)
return (error);
Expand All @@ -5092,13 +5118,15 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* we write anything to the pool because we'd need to update the space
* accounting using the deflated sizes.
*/
spa_import_progress_set_notes(spa, "Calculating deflated space");
spa_update_dspace(spa);

/*
* We have now retrieved all the information we needed to open the
* pool. If we are importing the pool in read-write mode, a few
* additional steps must be performed to finish the import.
*/
spa_import_progress_set_notes(spa, "Starting import");
if (spa_writeable(spa) && (spa->spa_load_state == SPA_LOAD_RECOVER ||
spa->spa_load_max_txg == UINT64_MAX)) {
uint64_t config_cache_txg = spa->spa_config_txg;
Expand All @@ -5122,6 +5150,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
(u_longlong_t)spa->spa_uberblock.ub_checkpoint_txg);
}

spa_import_progress_set_notes(spa, "Claiming ZIL blocks");
/*
* Traverse the ZIL and claim all blocks.
*/
Expand All @@ -5141,13 +5170,15 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* will have been set for us by ZIL traversal operations
* performed above.
*/
spa_import_progress_set_notes(spa, "Syncing ZIL claims");
txg_wait_synced(spa->spa_dsl_pool, spa->spa_claim_max_txg);

/*
* Check if we need to request an update of the config. On the
* next sync, we would update the config stored in vdev labels
* and the cachefile (by default /etc/zfs/zpool.cache).
*/
spa_import_progress_set_notes(spa, "Updating configs");
spa_ld_check_for_config_update(spa, config_cache_txg,
update_config_cache);

Expand All @@ -5156,6 +5187,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* Then check all DTLs to see if anything needs resilvering.
* The resilver will be deferred if a rebuild was started.
*/
spa_import_progress_set_notes(spa, "Starting resilvers");
if (vdev_rebuild_active(spa->spa_root_vdev)) {
vdev_rebuild_restart(spa);
} else if (!dsl_scan_resilvering(spa->spa_dsl_pool) &&
Expand All @@ -5169,6 +5201,8 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
*/
spa_history_log_version(spa, "open", NULL);

spa_import_progress_set_notes(spa,
"Restarting device removals");
spa_restart_removal(spa);
spa_spawn_aux_threads(spa);

Expand All @@ -5181,19 +5215,26 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, const char **ereport)
* auxiliary threads above (from which the livelist
* deletion zthr is part of).
*/
spa_import_progress_set_notes(spa,
"Cleaning up inconsistent objsets");
(void) dmu_objset_find(spa_name(spa),
dsl_destroy_inconsistent, NULL, DS_FIND_CHILDREN);

/*
* Clean up any stale temporary dataset userrefs.
*/
spa_import_progress_set_notes(spa,
"Cleaning up temporary userrefs");
dsl_pool_clean_tmp_userrefs(spa->spa_dsl_pool);

spa_config_enter(spa, SCL_CONFIG, FTAG, RW_READER);
spa_import_progress_set_notes(spa, "Restarting Initialize");
vdev_initialize_restart(spa->spa_root_vdev);
spa_import_progress_set_notes(spa, "Restarting TRIM");
vdev_trim_restart(spa->spa_root_vdev);
vdev_autotrim_restart(spa);
spa_config_exit(spa, SCL_CONFIG, FTAG);
spa_import_progress_set_notes(spa, "Finished importing");
}

spa_import_progress_remove(spa_guid(spa));
Expand Down
9 changes: 9 additions & 0 deletions module/zfs/spa_log_spacemap.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1153,6 +1153,7 @@ spa_ld_log_sm_data(spa_t *spa)

uint_t pn = 0;
uint64_t ps = 0;
uint64_t nsm = 0;
psls = sls = avl_first(&spa->spa_sm_logs_by_txg);
while (sls != NULL) {
/* Prefetch log spacemaps up to 16 TXGs or MBs ahead. */
Expand Down Expand Up @@ -1185,6 +1186,13 @@ spa_ld_log_sm_data(spa_t *spa)
summary_add_data(spa, sls->sls_txg,
sls->sls_mscount, 0, sls->sls_nblocks);

char buf[128];
(void) snprintf(buf, sizeof (buf),
"read %llu of %llu log space maps",
(u_longlong_t)nsm,
(u_longlong_t)avl_numnodes(&spa->spa_sm_logs_by_txg));
spa_import_progress_set_notes_nolog(spa, buf);

struct spa_ld_log_sm_arg vla = {
.slls_spa = spa,
.slls_txg = sls->sls_txg
Expand All @@ -1200,6 +1208,7 @@ spa_ld_log_sm_data(spa_t *spa)

pn--;
ps -= space_map_length(sls->sls_sm);
nsm++;
space_map_close(sls->sls_sm);
sls->sls_sm = NULL;
sls = AVL_NEXT(&spa->spa_sm_logs_by_txg, sls);
Expand Down
65 changes: 61 additions & 4 deletions module/zfs/spa_misc.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -426,6 +426,8 @@ spa_load_note(spa_t *spa, const char *fmt, ...)

zfs_dbgmsg("spa_load(%s, config %s): %s", spa->spa_name,
spa->spa_trust_config ? "trusted" : "untrusted", buf);

spa_import_progress_set_notes_nolog(spa, buf);
}

/*
Expand Down Expand Up @@ -2184,6 +2186,7 @@ typedef struct spa_import_progress {
uint64_t pool_guid; /* unique id for updates */
char *pool_name;
spa_load_state_t spa_load_state;
char *spa_load_notes;
uint64_t mmp_sec_remaining; /* MMP activity check */
uint64_t spa_load_max_txg; /* rewind txg */
procfs_list_node_t smh_node;
Expand All @@ -2194,9 +2197,9 @@ spa_history_list_t *spa_import_progress_list = NULL;
static int
spa_import_progress_show_header(struct seq_file *f)
{
seq_printf(f, "%-20s %-14s %-14s %-12s %s\n", "pool_guid",
seq_printf(f, "%-20s %-14s %-14s %-12s %s %s\n", "pool_guid",
"load_state", "multihost_secs", "max_txg",
"pool_name");
"pool_name", "notes");
return (0);
}

Expand All @@ -2205,11 +2208,12 @@ spa_import_progress_show(struct seq_file *f, void *data)
{
spa_import_progress_t *sip = (spa_import_progress_t *)data;

seq_printf(f, "%-20llu %-14llu %-14llu %-12llu %s\n",
seq_printf(f, "%-20llu %-14llu %-14llu %-12llu %s %s\n",
(u_longlong_t)sip->pool_guid, (u_longlong_t)sip->spa_load_state,
(u_longlong_t)sip->mmp_sec_remaining,
(u_longlong_t)sip->spa_load_max_txg,
(sip->pool_name ? sip->pool_name : "-"));
(sip->pool_name ? sip->pool_name : "-"),
(sip->spa_load_notes ? sip->spa_load_notes : "-"));

return (0);
}
Expand All @@ -2223,6 +2227,8 @@ spa_import_progress_truncate(spa_history_list_t *shl, unsigned int size)
sip = list_remove_head(&shl->procfs_list.pl_list);
if (sip->pool_name)
spa_strfree(sip->pool_name);
if (sip->spa_load_notes)
spa_strfree(sip->spa_load_notes);
kmem_free(sip, sizeof (spa_import_progress_t));
shl->size--;
}
Expand Down Expand Up @@ -2278,6 +2284,10 @@ spa_import_progress_set_state(uint64_t pool_guid,
sip = list_prev(&shl->procfs_list.pl_list, sip)) {
if (sip->pool_guid == pool_guid) {
sip->spa_load_state = load_state;
if (sip->spa_load_notes != NULL) {
spa_strfree(sip->spa_load_notes);
sip->spa_load_notes = NULL;
}
error = 0;
break;
}
Expand All @@ -2287,6 +2297,50 @@ spa_import_progress_set_state(uint64_t pool_guid,
return (error);
}

static void
spa_import_progress_set_notes_impl(spa_t *spa, const char *notes,
boolean_t log_dbgmsg)
{
spa_history_list_t *shl = spa_import_progress_list;
spa_import_progress_t *sip;
uint64_t pool_guid = spa_guid(spa);

if (shl->size == 0)
return;

mutex_enter(&shl->procfs_list.pl_lock);
for (sip = list_tail(&shl->procfs_list.pl_list); sip != NULL;
sip = list_prev(&shl->procfs_list.pl_list, sip)) {
if (sip->pool_guid == pool_guid) {
if (sip->spa_load_notes != NULL) {
spa_strfree(sip->spa_load_notes);
sip->spa_load_notes = NULL;
}
if (notes != NULL) {
sip->spa_load_notes = spa_strdup(notes);
if (log_dbgmsg) {
zfs_dbgmsg("'%s' %s", sip->pool_name,
notes);
}
}
break;
}
}
mutex_exit(&shl->procfs_list.pl_lock);
}

void
spa_import_progress_set_notes(spa_t *spa, const char *notes)
{
spa_import_progress_set_notes_impl(spa, notes, B_TRUE);
}

void
spa_import_progress_set_notes_nolog(spa_t *spa, const char *notes)
{
spa_import_progress_set_notes_impl(spa, notes, B_FALSE);
}

int
spa_import_progress_set_max_txg(uint64_t pool_guid, uint64_t load_max_txg)
{
Expand Down Expand Up @@ -2355,6 +2409,7 @@ spa_import_progress_add(spa_t *spa)
poolname = spa_name(spa);
sip->pool_name = spa_strdup(poolname);
sip->spa_load_state = spa_load_state(spa);
sip->spa_load_notes = NULL;

mutex_enter(&shl->procfs_list.pl_lock);
procfs_list_add(&shl->procfs_list, sip);
Expand All @@ -2374,6 +2429,8 @@ spa_import_progress_remove(uint64_t pool_guid)
if (sip->pool_guid == pool_guid) {
if (sip->pool_name)
spa_strfree(sip->pool_name);
if (sip->spa_load_notes)
spa_strfree(sip->spa_load_notes);
list_remove(&shl->procfs_list.pl_list, sip);
shl->size--;
kmem_free(sip, sizeof (spa_import_progress_t));
Expand Down
3 changes: 2 additions & 1 deletion tests/runfiles/linux.run
View file
Original file line number Diff line number Diff line change
Expand Up @@ -86,7 +86,8 @@ tags = ['functional', 'cli_root', 'zpool_expand']
tests = ['zpool_import_hostid_changed',
'zpool_import_hostid_changed_unclean_export',
'zpool_import_hostid_changed_cachefile',
'zpool_import_hostid_changed_cachefile_unclean_export']
'zpool_import_hostid_changed_cachefile_unclean_export',
'zpool_import_status']
tags = ['functional', 'cli_root', 'zpool_import']

[tests/functional/cli_root/zpool_reopen:Linux]
Expand Down
Loading

0 comments on commit 517fb73

Please sign in to comment.