Skip to content

Commit

Permalink
zpool import progress reports for long imports
Browse files Browse the repository at this point in the history 
When an import requires a long MMP activity check, or when the user
requests pool recovery, the import make take a long time.  The user may
not know why, or be able to tell whether the import is progressing or is
hung.

Add a new option to "zpool import", "-v" (for verbose).

When the -v option is used, create an additional thread which
periodically checks the contents of kstat/zfs/import_progress.  If the
import does not finish quickly, it reports the following on stdout:
* Name and guid of pool being imported
* User-friendly version of spa_load_state
* Expected time import will complete
* the max txg if recovering the pool

If one or more of these values change, the thread prints a new record.

A new record will be printed to stdout with a maximum frequency of one
per second so as not to spam the user.  As a result the printed output
may reflect only some of the import states transitioned through.

Use import kstat to check for Multihost activity check in relevant
tests, instead of using import duration, which works poorly when testing
on a slow machine.

Sample output:

	Pool tank1 (guid 4591991398949870326):
	Checking for a remote import.
	Check will complete by Tue Apr 16 08:43:58 2019

	Pool tank1 (guid 4591991398949870326):
	Checking for a remote import.
	Check will complete by Tue Apr 16 08:44:43 2019
	Recovering Pool max txg 745

Signed-off-by: Olaf Faaland <faaland1@llnl.gov>
  • Loading branch information
@ofaaland
ofaaland committed Oct 24, 2021
1 parent c641f54 commit c7b9aa8
Show file tree
Hide file tree
Showing 3 changed files with 205 additions and 9 deletions.
181 changes: 180 additions & 1 deletion cmd/zpool/zpool_main.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3436,6 +3436,160 @@ zpool_do_checkpoint(int argc, char **argv)

#define CHECKPOINT_OPT 1024

/*
* User-friendly strings for spa_load_state_t
*/
static const char * const load_state_names[] = {
[SPA_LOAD_NONE] = "Import Complete",
[SPA_LOAD_OPEN] = "Importing",
[SPA_LOAD_IMPORT] = "Importing",
[SPA_LOAD_TRYIMPORT] = "Verifying Configuration",
[SPA_LOAD_RECOVER] = "Recovering Pool",
[SPA_LOAD_ERROR] = "Import Error",
[SPA_LOAD_CREATE] = "Importing"
};

typedef struct import_progress_args {
boolean_t import_done;
} import_progress_args_t;

/*
* SILENT_SECS is amount of time we think user will wait before
* thinking something is broken. SLEEP_USEC is time between
* checks to see if import is done or state changed.
*/
#define PROGRESS_SILENT_SECS 10
#define PROGRESS_PERIOD_SECS 5
#define PROGRESS_SLEEP_USEC 100*1000

#define KSTAT_NAME "import_progress"

static void *
report_import_progress_thread(void *arg)
{
import_progress_args_t *pa = arg;
struct timespec start = {0};
struct timespec last_report = {0};
u_longlong_t last_pool_guid = 0;
u_longlong_t last_max_txg = 0;
time_t last_multihost_finish = 0;
int rc = 0;

(void) clock_gettime(CLOCK_MONOTONIC, &start);
while (pa->import_done == B_FALSE && rc >= 0) {
char *pool_name;
ssize_t count;
u_longlong_t load_state;
u_longlong_t pool_guid;
u_longlong_t multihost_secs;
u_longlong_t max_txg;
char kstat_buf[512];
char mmp_status_buf[100];
char pool_rewind_buf[100];
char *bufp;
struct timespec now = {0};

(void) clock_gettime(CLOCK_MONOTONIC, &now);

if ((now.tv_sec - start.tv_sec) < PROGRESS_SILENT_SECS) {
usleep(PROGRESS_SLEEP_USEC);
continue;
}

if ((now.tv_sec - last_report.tv_sec) < PROGRESS_PERIOD_SECS) {
usleep(PROGRESS_SLEEP_USEC);
continue;
}

/*
* If count == -ENOMEM, do not complain. The kstat buffer
* contents will get smaller as imports complete, and we
* try again anyway.
*/
bzero(kstat_buf, sizeof (kstat_buf));
count = kstat_read(KSTAT_NAME, kstat_buf, sizeof (kstat_buf));
if (count < 0) {
if (errno != ENOMEM) {
fprintf(stderr,
"Import monitor: read kstat fail %d\n",
errno);
}
usleep(PROGRESS_SLEEP_USEC);
continue;
}

/* Skip header line */
bufp = strchr(kstat_buf, '\n');
if (bufp == NULL) {
usleep(PROGRESS_SLEEP_USEC);
continue;
}

pool_name = NULL;
count = sscanf(bufp, "%llu %llu %llu %llu %ms\n", &pool_guid,
&load_state, &multihost_secs, &max_txg, &pool_name);

if (count < 5) {
fprintf(stderr, "Import monitor failure: "
"unable to parse %s\n", kstat_buf);
usleep(PROGRESS_SLEEP_USEC);
continue;
}

(void) clock_gettime(CLOCK_MONOTONIC, &last_report);

/* User needs to see wall-clock time */
time_t multihost_finish = time(NULL) + multihost_secs;

mmp_status_buf[0] = '\0';
pool_rewind_buf[0] = '\0';

if (pool_guid != last_pool_guid ||
multihost_finish != last_multihost_finish) {
struct tm tms;
char timestr[30];

tzset();
(void) strftime(timestr, sizeof (timestr), "%F %T",
localtime_r(&multihost_finish, &tms));
(void) snprintf(mmp_status_buf, sizeof (mmp_status_buf),
"Multihost is checking for a remote import.\nCheck "
"will complete by %s", timestr);
}

if ((pool_guid != last_pool_guid ||
max_txg != last_max_txg) &&
max_txg != 0) {
snprintf(pool_rewind_buf,
sizeof (pool_rewind_buf), "%s rewind txg "
"%llu\n", load_state_names[load_state],
max_txg);
}

if (mmp_status_buf[0] != '\0' ||
pool_rewind_buf[0] != '\0') {
printf("Pool %s (guid %llu):\n%s%s\n",
pool_name, pool_guid, mmp_status_buf,
pool_rewind_buf);
}

last_pool_guid = pool_guid;
last_multihost_finish = multihost_finish;
last_max_txg = max_txg;

free(pool_name);
usleep(PROGRESS_SLEEP_USEC);
}

if (rc < 0) {
fprintf(stderr, "kstat %s is not available to monitor the "
"progress of the import. The import is "
"continuing.\n", KSTAT_NAME);
}

return (NULL);
}

/*
* zpool import [-d dir] [-D]
* import [-o mntopts] [-o prop=value] ... [-R root] [-D] [-l]
Expand Down Expand Up @@ -3488,6 +3642,9 @@ zpool_do_checkpoint(int argc, char **argv)
* --rewind-to-checkpoint
* Import the pool and revert back to the checkpoint.
*
* -v Report import progress periodically, for slow imports.
*
*
* The import command scans for pools to import, and import pools based on pool
* name and GUID. The pool can also be renamed as part of the import process.
*/
Expand All @@ -3514,20 +3671,24 @@ zpool_do_import(int argc, char **argv)
boolean_t do_rewind = B_FALSE;
boolean_t xtreme_rewind = B_FALSE;
boolean_t do_scan = B_FALSE;
boolean_t do_verbose = B_FALSE;
boolean_t pool_exists = B_FALSE;
boolean_t pool_specified = B_FALSE;
uint64_t txg = -1ULL;
char *cachefile = NULL;
importargs_t idata = { 0 };
char *endptr;

pthread_t tid;
import_progress_args_t pa = { B_FALSE };

struct option long_options[] = {
{"rewind-to-checkpoint", no_argument, NULL, CHECKPOINT_OPT},
{0, 0, 0, 0}
};

/* check options */
while ((c = getopt_long(argc, argv, ":aCc:d:DEfFlmnNo:R:stT:VX",
while ((c = getopt_long(argc, argv, ":aCc:d:DEfFlmnNo:R:stT:vVX",
long_options, NULL)) != -1) {
switch (c) {
case 'a':
Expand Down Expand Up @@ -3601,6 +3762,9 @@ zpool_do_import(int argc, char **argv)
}
rewind_policy = ZPOOL_DO_REWIND | ZPOOL_EXTREME_REWIND;
break;
case 'v':
do_verbose = B_TRUE;
break;
case 'V':
flags |= ZFS_IMPORT_VERBATIM;
break;
Expand Down Expand Up @@ -3749,6 +3913,15 @@ zpool_do_import(int argc, char **argv)
idata.scan = do_scan;
idata.policy = policy;

if (do_verbose) {
int pthread_err;
pthread_err = pthread_create(&tid, NULL,
report_import_progress_thread, &pa);
if (err)
fprintf(stderr, "Unable to report progress: "
"err %d. Import will continue.\n", pthread_err);
}

pools = zpool_search_import(g_zfs, &idata, &libzfs_config_ops);

if (pools != NULL && pool_exists &&
Expand Down Expand Up @@ -3813,6 +3986,12 @@ zpool_do_import(int argc, char **argv)
do_destroyed, pool_specified, do_all, &idata);
}

if (do_verbose) {
pa.import_done = B_TRUE;
(void) pthread_cancel(tid);
(void) pthread_join(tid, NULL);
}

error:
nvlist_free(props);
nvlist_free(pools);
Expand Down
26 changes: 18 additions & 8 deletions tests/zfs-tests/tests/functional/mmp/mmp.kshlib
View file
Original file line number Diff line number Diff line change
Expand Up @@ -206,36 +206,46 @@ function import_no_activity_check # pool opts
{
typeset pool=$1
typeset opts=$2

typeset max_duration=$((MMP_TEST_DURATION_DEFAULT-1))
typeset tmpfile=$(mktemp)

SECONDS=0
zpool import $opts $pool
zpool import $opts -v $pool > $tmpfile 2>&1
typeset rc=$?
cat $tmpfile

if [[ $SECONDS -gt $max_duration ]]; then
log_fail "ERROR: import_no_activity_check unexpected activity \
check (${SECONDS}s gt $max_duration)"
if grep "Multihost is checking" $tmpfile; then
log_note $(grep "Multihost is checking" $tmpfile)
log_fail "ERROR: import_no_activity_check unexpected \
activity check reported"
fi

rm $tmpfile
return $rc
}

function import_activity_check # pool opts act_test_duration
{
typeset pool=$1
typeset opts=$2
typeset min_duration=${3:-$MMP_TEST_DURATION_DEFAULT}
typeset min_duration=${4:-$MMP_TEST_DURATION_DEFAULT}
typeset tmpfile=$(mktemp)

SECONDS=0
zpool import $opts $pool
zpool import -v $opts $pool > $tmpfile 2>&1
typeset rc=$?
cat $tmpfile

if [[ $SECONDS -le $min_duration ]]; then
log_fail "ERROR: import_activity_check expected activity check \
(${SECONDS}s le min_duration $min_duration)"
fi

if ! grep "use .zpool import -f" $tmpfile && ! grep "Multihost is checking" $tmpfile; then
log_fail "ERROR: import_activity_check expected \
Multihost status message"
fi

rm $tmpfile
return $rc
}

Expand Down
7 changes: 7 additions & 0 deletions tests/zfs-tests/tests/functional/mmp/mmp_inactive_import.ksh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -62,19 +62,22 @@ for opt in "" "-f"; do
done

# 3. Verify multihost=off and hostids differ (no activity check)
log_note "3. Verify multihost=off and hostids differ"
log_must zpool export -F $TESTPOOL
log_must mmp_clear_hostid
log_must mmp_set_hostid $HOSTID2
log_mustnot import_no_activity_check $TESTPOOL ""
log_must import_no_activity_check $TESTPOOL "-f"

# 4. Verify multihost=off and hostid zero allowed (no activity check)
log_note "4. Verify multihost=off and hostid zero allowed"
log_must zpool export -F $TESTPOOL
log_must mmp_clear_hostid
log_mustnot import_no_activity_check $TESTPOOL ""
log_must import_no_activity_check $TESTPOOL "-f"

# 5. Verify multihost=on and hostids match (no activity check)
log_note "5. Verify multihost=on and hostids match"
log_must mmp_pool_set_hostid $TESTPOOL $HOSTID1
log_must zpool set multihost=on $TESTPOOL

Expand All @@ -84,23 +87,27 @@ for opt in "" "-f"; do
done

# 6. Verify multihost=on and hostids differ (activity check)
log_note "6. Verify multihost=on and hostids differ"
log_must zpool export -F $TESTPOOL
log_must mmp_clear_hostid
log_must mmp_set_hostid $HOSTID2
log_mustnot import_activity_check $TESTPOOL ""
log_must import_activity_check $TESTPOOL "-f"

# 7. Verify mmp_write and mmp_fail are set correctly
log_note "7. Verify mmp_write and mmp_fail are set correctly"
log_must zpool export -F $TESTPOOL
log_must verify_mmp_write_fail_present ${DISK[0]}

# 8. Verify multihost=on and hostid zero fails (no activity check)
log_note "8. Verify multihost=on and hostid zero fails (no activity check)"
log_must mmp_clear_hostid
MMP_IMPORTED_MSG="Set a unique system hostid"
log_must check_pool_import $TESTPOOL "-f" "action" "$MMP_IMPORTED_MSG"
log_mustnot import_no_activity_check $TESTPOOL "-f"

# 9. Verify activity check duration based on mmp_write and mmp_fail
log_note "9. Verify activity check duration based on mmp_write and mmp_fail"
# Specify a short test via tunables but import pool imported while
# tunables set to default duration.
log_must set_tunable64 MULTIHOST_INTERVAL $MMP_INTERVAL_MIN
Expand Down

0 comments on commit c7b9aa8

Please sign in to comment.