zpool import progress indicator

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 kstat which lists all imports currently being processed by the
kernel (currently only one at a time is possible, but the kstat allows
for more than one).  The kstat is at
/proc/spl/kstat/zfs/import_progress.

In the zpool utility, create an additional thread which periodically
checks the contents of this kstat.  If the import does not finish
quickly, it reports the following on stderr:
* Name and guid of pool being imported
* User-friendly version of spa_load_state
* spa_load_max_txg

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

A new record will be printed to stderr 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.

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 <[email protected]>

cmd/zpool/zpool_main.c

@@ -2937,6 +2937,128 @@ zpool_do_checkpoint(int argc, char **argv)
 
 #define	CHECKPOINT_OPT	1024
 
+/*
+ * User-friendly strings for spa_load_state_t
+ */
+static char *load_state_names[] = {
+	"Import Complete",
+	"Importing",
+	"Importing",
+	"Verifying Configuration",
+	"Recovering Pool",
+	"Import Error",
+	"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	IMPORT_PROGRESS_SILENT_SECS	10
+#define	IMPORT_PROGRESS_PERIOD_SECS	1
+#define	IMPORT_PROGRESS_SLEEP_USEC	100*1000
+
+static void *
+report_import_progress_thread(void *arg)
+{
+	char path[] = "/proc/spl/kstat/zfs/import_progress";
+	import_progress_args_t *pa = arg;
+	time_t start_time = time(NULL);
+	time_t last_report = 0;
+	unsigned long long last_pool_guid = 0;
+	unsigned long long last_check_end = 0;
+	unsigned long long last_max_txg = 0;
+
+	ASSERT(arg);
+
+	while (pa->import_done == B_FALSE) {
+		FILE *import_kstat;
+		char *pool_name;
+		int count;
+		unsigned long long load_state;
+		unsigned long long check_start;
+		unsigned long long pool_guid;
+		unsigned long long check_end;
+		unsigned long long max_txg;
+		char mmp_status_buf[100];
+		char pool_rewind_buf[100];
+
+		if ((time(NULL) - start_time) < IMPORT_PROGRESS_SILENT_SECS)
+			continue;
+
+		if ((time(NULL) - last_report) < IMPORT_PROGRESS_PERIOD_SECS)
+			continue;
+
+		last_report = time(NULL);
+
+		import_kstat = fopen(path, "r");
+		if (import_kstat == NULL) {
+			fprintf(stderr, "%s is not available to monitor the "
+			    "progress of the import.  However the import is "
+			    "continuing.\n", path);
+			break;
+		}
+
+		/* Skip header line */
+		for (int c = fgetc(import_kstat); c != EOF && c != '\n';
+		    c = fgetc(import_kstat))
+			;
+
+		count = fscanf(import_kstat, "%llu %llu %llu %llu %llu %ms\n",
+		    &pool_guid, &load_state, &check_start, &check_end,
+		    &max_txg, &pool_name);
+
+		if (count == 6) {
+			mmp_status_buf[0] = '\0';
+			pool_rewind_buf[0] = '\0';
+
+			if ((pool_guid != last_pool_guid ||
+			    check_end != last_check_end) &&
+			    check_end > time(NULL)) {
+				time_t check_end_time = check_end;
+
+				snprintf(mmp_status_buf,
+				    sizeof (mmp_status_buf), "Multihost is "
+				    "checking for a remote import.\nCheck will "
+				    "complete by %s", ctime(&check_end_time));
+			}
+
+			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') {
+				fprintf(stderr, "Pool %s (guid %llu):\n%s%s\n",
+				    pool_name, pool_guid, mmp_status_buf,
+				    pool_rewind_buf);
+			}
+
+			last_pool_guid = pool_guid;
+			last_check_end = check_end;
+			last_max_txg = max_txg;
+
+			if (pool_name)
+				free(pool_name);
+		}
+
+		fclose(import_kstat);
+		usleep(IMPORT_PROGRESS_SLEEP_USEC);
+	}
+
+	return (NULL);
+}
+
 /*
  * zpool import [-d dir] [-D]
  *       import [-o mntopts] [-o prop=value] ... [-R root] [-D] [-l]
@@ -3022,6 +3144,9 @@ 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}
@@ -3261,6 +3386,14 @@ zpool_do_import(int argc, char **argv)
 	idata.scan = do_scan;
 	idata.policy = policy;
 
+	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 &&
@@ -3382,6 +3515,10 @@ zpool_do_import(int argc, char **argv)
 		}
 	}
 
+	pa.import_done = B_TRUE;
+	(void) pthread_cancel(tid);
+	(void) pthread_join(tid, NULL);
+
 	/*
 	 * If we were just looking for pools, report an error if none were
 	 * found.

include/sys/spa.h

@@ -965,6 +965,14 @@ extern void spa_iostats_trim_add(spa_t *spa, trim_type_t type,
     uint64_t extents_written, uint64_t bytes_written,
     uint64_t extents_skipped, uint64_t bytes_skipped,
     uint64_t extents_failed, uint64_t bytes_failed);
+extern void spa_import_progress_add(spa_t *spa);
+extern void spa_import_progress_remove(uint64_t spa_guid);
+extern int spa_import_progress_set_mmp_check(uint64_t pool_guid,
+    uint64_t check_start, uint64_t check_end);
+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);
 
 /* Pool configuration locks */
 extern int spa_config_tryenter(spa_t *spa, int locks, void *tag, krw_t rw);

module/zfs/spa.c

@@ -1437,6 +1437,7 @@ spa_unload(spa_t *spa)
 
 	ASSERT(MUTEX_HELD(&spa_namespace_lock));
 
+	spa_import_progress_remove(spa_guid(spa));
 	spa_load_note(spa, "UNLOADING");
 
 	/*
@@ -2469,6 +2470,7 @@ spa_activity_check_required(spa_t *spa, uberblock_t *ub, nvlist_t *label,
 	 */
 	if (ub->ub_mmp_magic == MMP_MAGIC && ub->ub_mmp_delay == 0)
 		return (B_FALSE);
+
 	/*
 	 * If the tryconfig_ values are nonzero, they are the results of an
 	 * earlier tryimport.  If they all match the uberblock we just found,
@@ -2617,8 +2619,12 @@ spa_activity_check(spa_t *spa, uberblock_t *ub, nvlist_t *config)
 	import_delay = spa_activity_check_duration(spa, ub);
 
 	/* Add a small random factor in case of simultaneous imports (0-25%) */
-	import_expire = gethrtime() + import_delay +
-	    (import_delay * spa_get_random(250) / 1000);
+	import_delay += import_delay * spa_get_random(250) / 1000;
+
+	import_expire = gethrtime() + import_delay;
+
+	(void) spa_import_progress_set_mmp_check(spa_guid(spa),
+	    gethrestime_sec(), gethrestime_sec() + NSEC2SEC(import_delay));
 
 	while (gethrtime() < import_expire) {
 		vdev_uberblock_load(rvd, ub, &mmp_label);
@@ -2987,6 +2993,13 @@ spa_ld_select_uberblock(spa_t *spa, spa_import_type_t type)
 		return (spa_vdev_err(rvd, VDEV_AUX_CORRUPT_DATA, ENXIO));
 	}
 
+	spa_import_progress_add(spa);
+	(void) spa_import_progress_set_state(spa_guid(spa),
+	    spa_load_state(spa));
+	if (spa->spa_load_max_txg != UINT64_MAX) {
+		(void) spa_import_progress_set_max_txg(spa_guid(spa),
+		    (u_longlong_t)spa->spa_load_max_txg);
+	}
 	spa_load_note(spa, "using uberblock with txg=%llu",
 	    (u_longlong_t)ub->ub_txg);
 
@@ -4346,6 +4359,7 @@ spa_load_impl(spa_t *spa, spa_import_type_t type, char **ereport)
 		spa_config_exit(spa, SCL_CONFIG, FTAG);
 	}
 
+	spa_import_progress_remove(spa_guid(spa));
 	spa_load_note(spa, "LOADED");
 
 	return (0);