diff --git a/cmd/zpool/zpool_main.c b/cmd/zpool/zpool_main.c index 3a2caa9a8101..13c0a642a2cd 100644 --- a/cmd/zpool/zpool_main.c +++ b/cmd/zpool/zpool_main.c @@ -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] @@ -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. */ @@ -3514,6 +3671,7 @@ 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; @@ -3521,13 +3679,16 @@ zpool_do_import(int argc, char **argv) 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': @@ -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; @@ -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 && @@ -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); diff --git a/tests/zfs-tests/tests/functional/mmp/mmp.kshlib b/tests/zfs-tests/tests/functional/mmp/mmp.kshlib index 661cbf3a52e7..a2177d48500e 100644 --- a/tests/zfs-tests/tests/functional/mmp/mmp.kshlib +++ b/tests/zfs-tests/tests/functional/mmp/mmp.kshlib @@ -206,18 +206,20 @@ 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 } @@ -225,17 +227,25 @@ 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 } diff --git a/tests/zfs-tests/tests/functional/mmp/mmp_inactive_import.ksh b/tests/zfs-tests/tests/functional/mmp/mmp_inactive_import.ksh index 6e7bb637548d..596bc2a29efe 100755 --- a/tests/zfs-tests/tests/functional/mmp/mmp_inactive_import.ksh +++ b/tests/zfs-tests/tests/functional/mmp/mmp_inactive_import.ksh @@ -62,6 +62,7 @@ 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 @@ -69,12 +70,14 @@ 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 @@ -84,6 +87,7 @@ 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 @@ -91,16 +95,19 @@ 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