Merge pull request #275 from versity/auke/qht_slow_umount_pr

Unmounts can be slow and break quorum-heartbeat-timeout

kmod/src/counters.h

@@ -145,7 +145,9 @@
 	EXPAND_COUNTER(lock_shrink_work)			\
 	EXPAND_COUNTER(lock_unlock)				\
 	EXPAND_COUNTER(lock_wait)				\
+	EXPAND_COUNTER(log_merge_complete)			\
 	EXPAND_COUNTER(log_merge_no_finalized)			\
+	EXPAND_COUNTER(log_merge_start)				\
 	EXPAND_COUNTER(log_merge_wait_timeout)			\
 	EXPAND_COUNTER(net_dropped_response)			\
 	EXPAND_COUNTER(net_send_bytes)				\
@@ -160,6 +162,7 @@
 	EXPAND_COUNTER(orphan_scan)				\
 	EXPAND_COUNTER(orphan_scan_attempts)			\
 	EXPAND_COUNTER(orphan_scan_cached)			\
+	EXPAND_COUNTER(orphan_scan_empty)			\
 	EXPAND_COUNTER(orphan_scan_error)			\
 	EXPAND_COUNTER(orphan_scan_item)			\
 	EXPAND_COUNTER(orphan_scan_omap_set)			\

kmod/src/inode.c

@@ -1637,10 +1637,14 @@ int scoutfs_inode_orphan_delete(struct super_block *sb, u64 ino, struct scoutfs_
 				struct scoutfs_lock *primary)
 {
 	struct scoutfs_key key;
+	int ret;
 
 	init_orphan_key(&key, ino);
 
-	return scoutfs_item_delete_force(sb, &key, lock, primary);
+	ret = scoutfs_item_delete_force(sb, &key, lock, primary);
+	trace_scoutfs_inode_orphan_delete(sb, ino, ret);
+
+	return ret;
 }
 
 /*
@@ -1722,6 +1726,8 @@ out:
 		scoutfs_release_trans(sb);
 	scoutfs_inode_index_unlock(sb, &ind_locks);
 
+	trace_scoutfs_delete_inode_end(sb, ino, mode, size, ret);
+
 	return ret;
 }
 
@@ -1817,6 +1823,9 @@ out:
  * they've checked that the inode could really be deleted.  We serialize
  * on a bit in the lock data so that we only have one deletion attempt
  * per inode under this mount's cluster lock.
+ *
+ * Returns -EAGAIN if we either did some cleanup work or are unable to finish
+ * cleaning up this inode right now.
  */
 static int try_delete_inode_items(struct super_block *sb, u64 ino)
 {
@@ -1830,6 +1839,8 @@ static int try_delete_inode_items(struct super_block *sb, u64 ino)
 	int bit_nr;
 	int ret;
 
+	trace_scoutfs_try_delete(sb, ino);
+
 	ret = scoutfs_lock_ino(sb, SCOUTFS_LOCK_WRITE, 0, ino, &lock);
 	if (ret < 0)
 		goto out;
@@ -1842,27 +1853,32 @@ static int try_delete_inode_items(struct super_block *sb, u64 ino)
 
 	/* only one local attempt per inode at a time */
 	if (test_and_set_bit(bit_nr, ldata->trying)) {
-		ret = 0;
+		trace_scoutfs_try_delete_local_busy(sb, ino);
+		ret = -EAGAIN;
 		goto out;
 	}
 	clear_trying = true;
 
 	/* can't delete if it's cached in local or remote mounts */
 	if (scoutfs_omap_test(sb, ino) || test_bit_le(bit_nr, ldata->map.bits)) {
-		ret = 0;
+		trace_scoutfs_try_delete_cached(sb, ino);
+		ret = -EAGAIN;
 		goto out;
 	}
 
 	scoutfs_inode_init_key(&key, ino);
 	ret = lookup_inode_item(sb, &key, &sinode, lock);
 	if (ret < 0) {
-		if (ret == -ENOENT)
+		if (ret == -ENOENT) {
+			trace_scoutfs_try_delete_no_item(sb, ino);
 			ret = 0;
+		}
 		goto out;
 	}
 
 	if (le32_to_cpu(sinode.nlink) > 0) {
-		ret = 0;
+		trace_scoutfs_try_delete_has_links(sb, ino, le32_to_cpu(sinode.nlink));
+		ret = -EAGAIN;
 		goto out;
 	}
 
@@ -1871,8 +1887,10 @@ static int try_delete_inode_items(struct super_block *sb, u64 ino)
 		goto out;
 
 	ret = delete_inode_items(sb, ino, &sinode, lock, orph_lock);
-	if (ret == 0)
+	if (ret == 0) {
+		ret = -EAGAIN;
 		scoutfs_inc_counter(sb, inode_deleted);
+	}
 
 out:
 	if (clear_trying)
@@ -2074,6 +2092,10 @@ void scoutfs_inode_schedule_orphan_dwork(struct super_block *sb)
  * a locally cached inode.  Then we ask the server for the open map
  * containing the inode.  Only if we don't see any cached users do we do
  * the expensive work of acquiring locks to try and delete the items.
+ *
+ * We need to track whether there is any orphan cleanup work remaining so
+ * that tests such as inode-deletion can watch the orphan_scan_empty counter
+ * to determine when inode cleanup from open-unlink scenarios is complete.
  */
 static void inode_orphan_scan_worker(struct work_struct *work)
 {
@@ -2085,11 +2107,14 @@ static void inode_orphan_scan_worker(struct work_struct *work)
 	SCOUTFS_BTREE_ITEM_REF(iref);
 	struct scoutfs_key last;
 	struct scoutfs_key key;
+	bool work_todo = false;
 	u64 group_nr;
 	int bit_nr;
 	u64 ino;
 	int ret;
 
+	trace_scoutfs_orphan_scan_start(sb);
+
 	scoutfs_inc_counter(sb, orphan_scan);
 
 	init_orphan_key(&last, U64_MAX);
@@ -2109,8 +2134,10 @@ static void inode_orphan_scan_worker(struct work_struct *work)
 		init_orphan_key(&key, ino);
 		ret = scoutfs_btree_next(sb, &roots.fs_root, &key, &iref);
 		if (ret < 0) {
-			if (ret == -ENOENT)
+			if (ret == -ENOENT) {
+				trace_scoutfs_orphan_scan_work(sb, 0);
 				break;
+			}
 			goto out;
 		}
 
@@ -2125,6 +2152,7 @@ static void inode_orphan_scan_worker(struct work_struct *work)
 
 		/* locally cached inodes will try to delete as they evict */
 		if (scoutfs_omap_test(sb, ino)) {
+			work_todo = true;
 			scoutfs_inc_counter(sb, orphan_scan_cached);
 			continue;
 		}
@@ -2140,13 +2168,22 @@ static void inode_orphan_scan_worker(struct work_struct *work)
 
 		/* remote cached inodes will also try to delete */
 		if (test_bit_le(bit_nr, omap.bits)) {
+			work_todo = true;
 			scoutfs_inc_counter(sb, orphan_scan_omap_set);
 			continue;
 		}
 
 		/* seemingly orphaned and unused, get locks and check for sure */
 		scoutfs_inc_counter(sb, orphan_scan_attempts);
+		trace_scoutfs_orphan_scan_work(sb, ino);
+
 		ret = try_delete_inode_items(sb, ino);
+		if (ret == -EAGAIN) {
+			work_todo = true;
+			ret = 0;
+		}
+
+		trace_scoutfs_orphan_scan_end(sb, ino, ret);
 	}
 
 	ret = 0;
@@ -2155,6 +2192,11 @@ out:
 	if (ret < 0)
 		scoutfs_inc_counter(sb, orphan_scan_error);
 
+	if (!work_todo)
+		scoutfs_inc_counter(sb, orphan_scan_empty);
+
+	trace_scoutfs_orphan_scan_stop(sb, work_todo);
+
 	scoutfs_inode_schedule_orphan_dwork(sb);
 }
 

kmod/src/scoutfs_trace.h

@@ -789,6 +789,80 @@ TRACE_EVENT(scoutfs_inode_walk_writeback,
 		  __entry->ino, __entry->write, __entry->ret)
 );
 
+TRACE_EVENT(scoutfs_orphan_scan_start,
+	TP_PROTO(struct super_block *sb),
+
+	TP_ARGS(sb),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+	),
+
+	TP_printk(SCSBF, SCSB_TRACE_ARGS)
+);
+
+TRACE_EVENT(scoutfs_orphan_scan_stop,
+	TP_PROTO(struct super_block *sb, bool work_todo),
+
+	TP_ARGS(sb, work_todo),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(bool, work_todo)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->work_todo = work_todo;
+	),
+
+	TP_printk(SCSBF" work_todo %d", SCSB_TRACE_ARGS, __entry->work_todo)
+);
+
+TRACE_EVENT(scoutfs_orphan_scan_work,
+	TP_PROTO(struct super_block *sb, __u64 ino),
+
+	TP_ARGS(sb, ino),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, ino)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->ino = ino;
+	),
+
+	TP_printk(SCSBF" ino %llu", SCSB_TRACE_ARGS,
+		  __entry->ino)
+);
+
+TRACE_EVENT(scoutfs_orphan_scan_end,
+	TP_PROTO(struct super_block *sb, __u64 ino, int ret),
+
+	TP_ARGS(sb, ino, ret),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, ino)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->ino = ino;
+		__entry->ret = ret;
+	),
+
+	TP_printk(SCSBF" ino %llu ret %d", SCSB_TRACE_ARGS,
+		  __entry->ino, __entry->ret)
+);
+
 DECLARE_EVENT_CLASS(scoutfs_lock_info_class,
 	TP_PROTO(struct super_block *sb, struct lock_info *linfo),
 
@@ -1036,6 +1110,82 @@ TRACE_EVENT(scoutfs_orphan_inode,
 		  MINOR(__entry->dev), __entry->ino)
 );
 
+DECLARE_EVENT_CLASS(scoutfs_try_delete_class,
+        TP_PROTO(struct super_block *sb, u64 ino),
+        TP_ARGS(sb, ino),
+        TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, ino)
+        ),
+        TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->ino = ino;
+        ),
+	TP_printk(SCSBF" ino %llu", SCSB_TRACE_ARGS, __entry->ino)
+);
+
+DEFINE_EVENT(scoutfs_try_delete_class, scoutfs_try_delete,
+        TP_PROTO(struct super_block *sb, u64 ino),
+        TP_ARGS(sb, ino)
+);
+
+DEFINE_EVENT(scoutfs_try_delete_class, scoutfs_try_delete_local_busy,
+        TP_PROTO(struct super_block *sb, u64 ino),
+        TP_ARGS(sb, ino)
+);
+
+DEFINE_EVENT(scoutfs_try_delete_class, scoutfs_try_delete_cached,
+        TP_PROTO(struct super_block *sb, u64 ino),
+        TP_ARGS(sb, ino)
+);
+
+DEFINE_EVENT(scoutfs_try_delete_class, scoutfs_try_delete_no_item,
+        TP_PROTO(struct super_block *sb, u64 ino),
+        TP_ARGS(sb, ino)
+);
+
+TRACE_EVENT(scoutfs_try_delete_has_links,
+	TP_PROTO(struct super_block *sb, u64 ino, unsigned int nlink),
+
+	TP_ARGS(sb, ino, nlink),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, ino)
+		__field(unsigned int, nlink)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->ino = ino;
+		__entry->nlink = nlink;
+	),
+
+	TP_printk(SCSBF" ino %llu nlink %u", SCSB_TRACE_ARGS, __entry->ino,
+		  __entry->nlink)
+);
+
+TRACE_EVENT(scoutfs_inode_orphan_delete,
+	TP_PROTO(struct super_block *sb, u64 ino, int ret),
+
+	TP_ARGS(sb, ino, ret),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, ino)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->ino = ino;
+		__entry->ret = ret;
+	),
+
+	TP_printk(SCSBF" ino %llu ret %d", SCSB_TRACE_ARGS, __entry->ino,
+		__entry->ret)
+);
+
 TRACE_EVENT(scoutfs_delete_inode,
 	TP_PROTO(struct super_block *sb, u64 ino, umode_t mode, u64 size),
 
@@ -1060,6 +1210,32 @@ TRACE_EVENT(scoutfs_delete_inode,
 		  __entry->mode, __entry->size)
 );
 
+TRACE_EVENT(scoutfs_delete_inode_end,
+	TP_PROTO(struct super_block *sb, u64 ino, umode_t mode, u64 size, int ret),
+
+	TP_ARGS(sb, ino, mode, size, ret),
+
+	TP_STRUCT__entry(
+		__field(dev_t, dev)
+		__field(__u64, ino)
+		__field(umode_t, mode)
+		__field(__u64, size)
+		__field(int, ret)
+	),
+
+	TP_fast_assign(
+		__entry->dev = sb->s_dev;
+		__entry->ino = ino;
+		__entry->mode = mode;
+		__entry->size = size;
+		__entry->ret = ret;
+	),
+
+	TP_printk("dev %d,%d ino %llu, mode 0x%x size %llu, ret %d",
+		  MAJOR(__entry->dev), MINOR(__entry->dev), __entry->ino,
+		  __entry->mode, __entry->size, __entry->ret)
+);
+
 DECLARE_EVENT_CLASS(scoutfs_key_class,
         TP_PROTO(struct super_block *sb, struct scoutfs_key *key),
         TP_ARGS(sb, key),
@@ -3097,6 +3273,24 @@ TRACE_EVENT(scoutfs_ioc_search_xattrs,
 		  __entry->ino, __entry->last_ino)
 );
 
+TRACE_EVENT(scoutfs_trigger_fired,
+	TP_PROTO(struct super_block *sb, const char *name),
+
+	TP_ARGS(sb, name),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(const char *, name)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->name = name;
+	),
+
+	TP_printk(SCSBF" %s", SCSB_TRACE_ARGS, __entry->name)
+);
+
 #endif /* _TRACE_SCOUTFS_H */
 
 /* This part must be outside protection */

kmod/src/server.c

@@ -41,6 +41,7 @@
 #include "recov.h"
 #include "omap.h"
 #include "fence.h"
+#include "triggers.h"
 
 /*
  * Every active mount can act as the server that listens on a net
@@ -1291,9 +1292,13 @@ static int finalize_and_start_log_merge(struct super_block *sb, struct scoutfs_l
 		 * meta was low so that deleted items are merged
 		 * promptly and freed blocks can bring the client out of
 		 * enospc.
+		 *
+		 * The trigger can be used to force a log merge in cases where
+		 * a test only generates small amounts of change.
 		 */
 		finalize_ours = (lt->item_root.height > 2) ||
-				(le32_to_cpu(lt->meta_avail.flags) & SCOUTFS_ALLOC_FLAG_LOW);
+				(le32_to_cpu(lt->meta_avail.flags) & SCOUTFS_ALLOC_FLAG_LOW) ||
+				scoutfs_trigger(sb, LOG_MERGE_FORCE_FINALIZE_OURS);
 
 		trace_scoutfs_server_finalize_decision(sb, rid, saw_finalized, others_active,
 						       ours_visible, finalize_ours, delay_ms,
@@ -1402,6 +1407,8 @@ static int finalize_and_start_log_merge(struct super_block *sb, struct scoutfs_l
 			BUG_ON(err); /* inconsistent */
 		}
 
+		scoutfs_inc_counter(sb, log_merge_start);
+
 		/* we're done, caller can make forward progress */
 		break;
 	}
@@ -1618,7 +1625,8 @@ static int server_get_log_trees(struct super_block *sb,
 		goto update;
 	}
 
-	ret = alloc_move_empty(sb, &super->data_alloc, &lt.data_freed, 100);
+	ret = alloc_move_empty(sb, &super->data_alloc, &lt.data_freed,
+			       COMMIT_HOLD_ALLOC_BUDGET / 2);
 	if (ret == -EINPROGRESS)
 		ret = 0;
 	if (ret < 0) {
@@ -1913,9 +1921,11 @@ static int reclaim_open_log_tree(struct super_block *sb, u64 rid)
 	       scoutfs_alloc_splice_list(sb, &server->alloc, &server->wri, server->other_freed,
 					 &lt.meta_avail)) ?:
 	      (err_str = "empty data_avail",
-	       alloc_move_empty(sb, &super->data_alloc, &lt.data_avail, 100)) ?:
+	       alloc_move_empty(sb, &super->data_alloc, &lt.data_avail,
+				COMMIT_HOLD_ALLOC_BUDGET / 2)) ?:
 	      (err_str = "empty data_freed",
-	       alloc_move_empty(sb, &super->data_alloc, &lt.data_freed, 100));
+	       alloc_move_empty(sb, &super->data_alloc, &lt.data_freed,
+				COMMIT_HOLD_ALLOC_BUDGET / 2));
 	mutex_unlock(&server->alloc_mutex);
 
 	/* only finalize, allowing merging, once the allocators are fully freed */
@@ -2506,6 +2516,8 @@ static int splice_log_merge_completions(struct super_block *sb,
 		queue_work(server->wq, &server->log_merge_free_work);
 	else
 		err_str = "deleting merge status item";
+
+	scoutfs_inc_counter(sb, log_merge_complete);
 out:
 	if (upd_stat) {
 		init_log_merge_key(&key, SCOUTFS_LOG_MERGE_STATUS_ZONE, 0, 0);
@@ -3036,7 +3048,13 @@ static int server_commit_log_merge(struct super_block *sb,
 				  SCOUTFS_LOG_MERGE_STATUS_ZONE, 0, 0,
 				  &stat, sizeof(stat));
 	if (ret < 0) {
-		err_str = "getting merge status item";
+		/*
+		 * During a retransmission, it's possible that the server
+		 * already committed and resolved this log merge. ENOENT
+		 * is expected in that case.
+		 */
+		if (ret != -ENOENT)
+			err_str = "getting merge status item";
 		goto out;
 	}
 

kmod/src/triggers.c

@@ -18,6 +18,7 @@
 
 #include "super.h"
 #include "triggers.h"
+#include "scoutfs_trace.h"
 
 /*
  * We have debugfs files we can write to which arm triggers which
@@ -39,6 +40,7 @@ struct scoutfs_triggers {
 
 static char *names[] = {
 	[SCOUTFS_TRIGGER_BLOCK_REMOVE_STALE] = "block_remove_stale",
+	[SCOUTFS_TRIGGER_LOG_MERGE_FORCE_FINALIZE_OURS] = "log_merge_force_finalize_ours",
 	[SCOUTFS_TRIGGER_SRCH_COMPACT_LOGS_PAD_SAFE] = "srch_compact_logs_pad_safe",
 	[SCOUTFS_TRIGGER_SRCH_FORCE_LOG_ROTATE] = "srch_force_log_rotate",
 	[SCOUTFS_TRIGGER_SRCH_MERGE_STOP_SAFE] = "srch_merge_stop_safe",
@@ -51,6 +53,7 @@ bool scoutfs_trigger_test_and_clear(struct super_block *sb, unsigned int t)
 	atomic_t *atom;
 	int old;
 	int mem;
+	bool fired;
 
 	BUG_ON(t >= SCOUTFS_TRIGGER_NR);
 	atom = &triggers->atomics[t];
@@ -64,7 +67,12 @@ bool scoutfs_trigger_test_and_clear(struct super_block *sb, unsigned int t)
 		mem = atomic_cmpxchg(atom, old, 0);
 	} while (mem && mem != old);
 
-	return !!mem;
+	fired = !!mem;
+
+	if (fired)
+		trace_scoutfs_trigger_fired(sb, names[t]);
+
+	return fired;
 }
 
 int scoutfs_setup_triggers(struct super_block *sb)

kmod/src/triggers.h

@@ -3,6 +3,7 @@
 
 enum scoutfs_trigger {
 	SCOUTFS_TRIGGER_BLOCK_REMOVE_STALE,
+	SCOUTFS_TRIGGER_LOG_MERGE_FORCE_FINALIZE_OURS,
 	SCOUTFS_TRIGGER_SRCH_COMPACT_LOGS_PAD_SAFE,
 	SCOUTFS_TRIGGER_SRCH_FORCE_LOG_ROTATE,
 	SCOUTFS_TRIGGER_SRCH_MERGE_STOP_SAFE,

tests/fenced-local-force-unmount.sh

@@ -9,7 +9,7 @@
 echo "$0 running rid '$SCOUTFS_FENCED_REQ_RID' ip '$SCOUTFS_FENCED_REQ_IP' args '$@'"
 
 echo_fail() {
-	echo "$@" >> /dev/stderr
+	echo "$@" >&2
 	exit 1
 }
 
@@ -27,8 +27,7 @@ for fs in /sys/fs/scoutfs/*; do
 	nr="$(quiet_cat $fs/data_device_maj_min)"
 	[ ! -d "$fs" -o "$fs_rid" != "$rid" ] && continue
 
-	mnt=$(findmnt -l -n -t scoutfs -o TARGET -S $nr) || \
-		echo_fail "findmnt -t scoutfs -S $nr failed"
+	mnt=$(findmnt -l -n -t scoutfs -o TARGET -S $nr)
 	[ -z "$mnt" ] && continue
 
 	if ! umount -qf "$mnt"; then

tests/funcs/filter.sh

@@ -170,6 +170,9 @@ t_filter_dmesg()
 	# some ci test guests are unresponsive
 	re="$re|longest quorum heartbeat .* delay"
 
+	# creating block devices may trigger this
+	re="$re|block device autoloading is deprecated and will be removed."
+
 	egrep -v "($re)" | \
 		ignore_harmless_unwind_kasan_stack_oob
 }

tests/funcs/fs.sh

@@ -498,3 +498,100 @@ t_restore_all_sysfs_mount_options() {
 		t_set_sysfs_mount_option $i $name "${_saved_opts[$ind]}"
 	done
 }
+
+t_force_log_merge() {
+	local sv=$(t_server_nr)
+	local merges_started
+	local last_merges_started
+	local merges_completed
+	local last_merges_completed
+
+	while true; do
+		last_merges_started=$(t_counter log_merge_start $sv)
+		last_merges_completed=$(t_counter log_merge_complete $sv)
+
+		t_trigger_arm_silent log_merge_force_finalize_ours $sv
+
+		t_sync_seq_index
+
+		while test "$(t_trigger_get log_merge_force_finalize_ours $sv)" == "1"; do
+			sleep .5
+		done
+
+		merges_started=$(t_counter log_merge_start $sv)
+
+		if (( merges_started > last_merges_started )); then
+			merges_completed=$(t_counter log_merge_complete $sv)
+
+			while (( merges_completed == last_merges_completed )); do
+				sleep .5
+				merges_completed=$(t_counter log_merge_complete $sv)
+			done
+			break
+		fi
+	done
+}
+
+declare -A _last_scan
+t_get_orphan_scan_runs() {
+	local i
+
+	for i in $(t_fs_nrs); do
+		_last_scan[$i]=$(t_counter orphan_scan $i)
+	done
+}
+
+t_wait_for_orphan_scan_runs() {
+	local i
+	local scan
+
+	t_get_orphan_scan_runs
+
+	for i in $(t_fs_nrs); do
+		while true; do
+			scan=$(t_counter orphan_scan $i)
+			if (( scan != _last_scan[$i] )); then
+				break
+			fi
+			sleep .5
+		done
+	done
+}
+
+declare -A _last_empty
+t_get_orphan_scan_empty() {
+	local i
+
+	for i in $(t_fs_nrs); do
+		_last_empty[$i]=$(t_counter orphan_scan_empty $i)
+	done
+}
+
+t_wait_for_no_orphans() {
+	local i;
+	local working;
+	local empty;
+
+	t_get_orphan_scan_empty
+
+	while true; do
+		working=0
+
+		t_wait_for_orphan_scan_runs
+
+		for i in $(t_fs_nrs); do
+			empty=$(t_counter orphan_scan_empty $i)
+			if (( empty == _last_empty[$i] )); then
+				(( working++ ))
+			else
+				(( _last_empty[$i] = empty ))
+			fi
+		done
+
+		if (( working == 0 )); then
+			break
+		fi
+
+		sleep 1
+	done
+}

tests/funcs/tap.sh

@@ -43,9 +43,14 @@ t_tap_progress()
 	local testname=$1
 	local result=$2
 
+	local stmsg=""
 	local diff=""
 	local dmsg=""
 
+	if [[ -s $T_RESULTS/tmp/${testname}/status.msg ]]; then
+		stmsg="1"
+	fi
+
 	if [[ -s "$T_RESULTS/tmp/${testname}/dmesg.new" ]]; then
 		dmsg="1"
 	fi
@@ -61,6 +66,7 @@ t_tap_progress()
 		echo "# ${testname} ** skipped - permitted **"
 	else
 		echo "not ok ${i} - ${testname}"
+
 		case ${result} in
 		101)
 			echo "# ${testname} ** skipped **"
@@ -70,6 +76,13 @@ t_tap_progress()
 			;;
 		esac
 
+		if [[ -n "${stmsg}" ]]; then
+			echo "#"
+			echo "# status:"
+			echo "#"
+			cat $T_RESULTS/tmp/${testname}/status.msg | sed 's/^/# - /'
+		fi
+
 		if [[ -n "${diff}" ]]; then
 			echo "#"
 			echo "# diff:"

tests/golden/inode-deletion

@@ -17,7 +17,7 @@ ino not found in dseq index
 mount 0 contents after mount 1 rm: contents
 ino found in dseq index
 ino found in dseq index
-stat: cannot stat '/mnt/test/test/inode-deletion/file': No such file or directory
+stat: cannot stat '/mnt/test/test/inode-deletion/badfile': No such file or directory
 ino not found in dseq index
 ino not found in dseq index
 == lots of deletions use one open map

tests/run-tests.sh

@@ -400,7 +400,8 @@ if [ -n "$T_INSMOD" ]; then
 fi
 
 if [ -n "$T_TRACE_MULT" ]; then
-	orig_trace_size=$(cat /sys/kernel/debug/tracing/buffer_size_kb)
+#	orig_trace_size=$(cat /sys/kernel/debug/tracing/buffer_size_kb)
+	orig_trace_size=1408
 	mult_trace_size=$((orig_trace_size * T_TRACE_MULT))
 	msg "increasing trace buffer size from $orig_trace_size KiB to $mult_trace_size KiB"
 	echo $mult_trace_size > /sys/kernel/debug/tracing/buffer_size_kb

tests/tests/get-referring-entries.sh

@@ -72,7 +72,7 @@ touch $T_D0/dir/file
 mkdir $T_D0/dir/dir
 ln -s $T_D0/dir/file $T_D0/dir/symlink
 mknod $T_D0/dir/char c 1 3 # null
-mknod $T_D0/dir/block b 7 0 # loop0
+mknod $T_D0/dir/block b 42 0 # SAMPLE block dev - nonexistant/demo use only number
 for name in $(ls -UA $T_D0/dir | sort); do
 	ino=$(stat -c '%i' $T_D0/dir/$name)
 	$GRE $ino | filter_types

tests/tests/inode-deletion.sh

@@ -61,18 +61,28 @@ rm -f "$T_D1/file"
 check_ino_index "$ino" "$dseq" "$T_M0"
 check_ino_index "$ino" "$dseq" "$T_M1"
 
+# Hurry along the orphan scanners. If any are currently asleep, we will
+# have to wait at least their current scan interval before they wake up,
+# run, and notice their new interval.
+t_save_all_sysfs_mount_options orphan_scan_delay_ms
+t_set_all_sysfs_mount_options orphan_scan_delay_ms 500
+t_wait_for_orphan_scan_runs
+
 echo "== unlink wait for open on other mount"
-echo "contents" > "$T_D0/file"
-ino=$(stat -c "%i" "$T_D0/file")
-dseq=$(scoutfs stat -s data_seq "$T_D0/file")
-exec {FD}<"$T_D0/file"
-rm -f "$T_D1/file"
+echo "contents" > "$T_D0/badfile"
+ino=$(stat -c "%i" "$T_D0/badfile")
+dseq=$(scoutfs stat -s data_seq "$T_D0/badfile")
+exec {FD}<"$T_D0/badfile"
+rm -f "$T_D1/badfile"
 echo "mount 0 contents after mount 1 rm: $(cat <&$FD)"
 check_ino_index "$ino" "$dseq" "$T_M0"
 check_ino_index "$ino" "$dseq" "$T_M1"
 exec {FD}>&-  # close
 # we know that revalidating will unhash the remote dentry
-stat "$T_D0/file" 2>&1 | sed 's/cannot statx/cannot stat/' | t_filter_fs
+stat "$T_D0/badfile" 2>&1 | sed 's/cannot statx/cannot stat/' | t_filter_fs
+t_force_log_merge
+# wait for orphan scanners to pick up the unlinked inode and become idle
+t_wait_for_no_orphans
 check_ino_index "$ino" "$dseq" "$T_M0"
 check_ino_index "$ino" "$dseq" "$T_M1"
 
@@ -83,16 +93,20 @@ rm -f "$T_D0/dir"/files-*
 rmdir "$T_D0/dir"
 
 echo "== open files survive remote scanning orphans"
-echo "contents" > "$T_D0/file"
-ino=$(stat -c "%i" "$T_D0/file")
-dseq=$(scoutfs stat -s data_seq "$T_D0/file")
-exec {FD}<"$T_D0/file"
-rm -f "$T_D0/file"
+echo "contents" > "$T_D0/lastfile"
+ino=$(stat -c "%i" "$T_D0/lastfile")
+dseq=$(scoutfs stat -s data_seq "$T_D0/lastfile")
+exec {FD}<"$T_D0/lastfile"
+rm -f "$T_D0/lastfile"
 t_umount 1
 t_mount 1
 echo "mount 0 contents after mount 1 remounted: $(cat <&$FD)"
 exec {FD}>&-  # close
+t_force_log_merge
+t_wait_for_no_orphans
 check_ino_index "$ino" "$dseq" "$T_M0"
 check_ino_index "$ino" "$dseq" "$T_M1"
 
+t_restore_all_sysfs_mount_options orphan_scan_delay_ms
+
 t_pass

tests/tests/quorum-heartbeat-timeout.sh

@@ -62,7 +62,7 @@ test_timeout()
 	sleep 1
 
 	# tear down the current server/leader
-	t_force_umount $sv
+	t_force_umount $sv &
 
 	# see how long it takes for the next leader to start
 	start=$(time_ms)
@@ -73,6 +73,7 @@ test_timeout()
 	echo "to $to delay $delay" >> $T_TMP.delay
 
 	# restore the mount that we tore down
+	wait
 	t_mount $sv
 
 	# make sure the new leader delay was reasonable, allowing for some slack

tests/tests/renameat2-noreplace.sh

@@ -8,19 +8,19 @@ t_require_mounts 2
 echo "=== renameat2 noreplace flag test"
 
 # give each mount their own dir (lock group) to minimize create contention
-mkdir $T_M0/dir0
-mkdir $T_M1/dir1
+mkdir $T_D0/dir0
+mkdir $T_D1/dir1
 
 echo "=== run two asynchronous calls to renameat2 NOREPLACE"
 for i in $(seq 0 100); do
         # prepare inputs in isolation
-        touch "$T_M0/dir0/old0"
-        touch "$T_M1/dir1/old1"
+        touch "$T_D0/dir0/old0"
+        touch "$T_D1/dir1/old1"
 
         # race doing noreplace renames, both can't succeed
-        dumb_renameat2 -n "$T_M0/dir0/old0" "$T_M0/dir0/sharednew" 2> /dev/null &
+        dumb_renameat2 -n "$T_D0/dir0/old0" "$T_D0/dir0/sharednew" 2> /dev/null &
         pid0=$!
-        dumb_renameat2 -n "$T_M1/dir1/old1" "$T_M1/dir0/sharednew" 2> /dev/null &
+        dumb_renameat2 -n "$T_D1/dir1/old1" "$T_D1/dir0/sharednew" 2> /dev/null &
         pid1=$!
 
         wait $pid0
@@ -31,7 +31,7 @@ for i in $(seq 0 100); do
         test "$rc0" == 0 -a "$rc1" == 0 && t_fail "both renames succeeded"
 
         # blow away possible files for either race outcome
-        rm -f "$T_M0/dir0/old0" "$T_M1/dir1/old1" "$T_M0/dir0/sharednew" "$T_M1/dir1/sharednew"
+        rm -f "$T_D0/dir0/old0" "$T_D1/dir1/old1" "$T_D0/dir0/sharednew" "$T_D1/dir1/sharednew"
 done
 
 t_pass

utils/fenced/scoutfs-fenced

@@ -7,7 +7,7 @@ message_output()
 
 error_message()
 {
-	message_output "$@" >> /dev/stderr
+	message_output "$@" >&2
 }
 
 error_exit()

utils/man/scoutfs.8

@@ -402,39 +402,25 @@ before destroying an old empty data device.
 .PD
 
 .TP
-.BI "print {-a|--allocs} {-i|--items ITEMS} {-r|--roots ROOTS} {-S|--skip-likely-huge} META-DEVICE"
+.BI "print {-S|--skip-likely-huge} META-DEVICE"
 .sp
-Prints out some or all of the metadata in the file system.  This makes no effort
+Prints out all of the metadata in the file system.  This makes no effort
 to ensure that the structures are consistent as they're traversed and
 can present structures that seem corrupt as they change as they're
 output.
-.sp
-Structures that are related to the number of mounts and are maintained at a
-relatively reasonable size are always printed. These include per-mount log
-trees, srch files, allocators, and the metadata allocators used by server
-commits. Other btrees and their items can be selected as desired.
 .RS 1.0i
 .PD 0
+.TP
 .sp
-.TP
-.B "-a, --allocs"
-Print the metadata and data allocators. Enabled by default.
-.TP
-.B "-r, --roots ROOTS"
-This option can be used to select which btrees are traversed. It is a comma-separated list containing one or more of the following btree roots: logs, srch, fs. Default is all roots.
-.TP
-.B "-i, --items ITEMS"
-This option can be used to choose which btree items are printed from the
-selected btree roots. It is a comma-separated list containing one or
-more of the following items: inode, xattr, dirent, symlink, backref, extent.
-Default is all items.
-.TP
 .B "-S, --skip-likely-huge"
 Skip printing structures that are likely to be very large.  The
 structures that are skipped tend to be global and whose size tends to be
 related to the size of the volume.   Examples of skipped structures include
 the global fs items, srch files, and metadata and data
-allocators.
+allocators.  Similar structures that are not skipped are related to the
+number of mounts and are maintained at a relatively reasonable size.
+These include per-mount log trees, srch files, allocators, and the
+metadata allocators used by server commits.
 .sp
 Skipping the larger structures limits the print output to a relatively
 constant size rather than being a large multiple of the used metadata

utils/src/print.c

@@ -29,42 +29,6 @@
 #include "leaf_item_hash.h"
 #include "dev.h"
 
-struct print_args {
-	char *meta_device;
-	bool skip_likely_huge;
-	bool roots_requested;
-	bool items_requested;
-	bool allocs_requested;
-	bool walk_allocs;
-	bool walk_logs_root;
-	bool walk_fs_root;
-	bool walk_srch_root;
-	bool print_inodes;
-	bool print_xattrs;
-	bool print_dirents;
-	bool print_symlinks;
-	bool print_backrefs;
-	bool print_extents;
-};
-
-static struct print_args print_args = {
-	.meta_device	  = NULL,
-	.skip_likely_huge = false,
-	.roots_requested  = false,
-	.items_requested  = false,
-	.allocs_requested = false,
-	.walk_allocs	  = true,
-	.walk_logs_root	  = true,
-	.walk_fs_root	  = true,
-	.walk_srch_root	  = true,
-	.print_inodes	  = true,
-	.print_xattrs	  = true,
-	.print_dirents	  = true,
-	.print_symlinks	  = true,
-	.print_backrefs	  = true,
-	.print_extents	  = true
-};
-
 static void print_block_header(struct scoutfs_block_header *hdr, int size)
 {
 	u32 crc = crc_block(hdr, size);
@@ -231,7 +195,7 @@ static void print_inode_index(struct scoutfs_key *key, void *val, int val_len)
 
 typedef void (*print_func_t)(struct scoutfs_key *key, void *val, int val_len);
 
-static print_func_t find_printer(u8 zone, u8 type, bool *suppress)
+static print_func_t find_printer(u8 zone, u8 type)
 {
 	if (zone == SCOUTFS_INODE_INDEX_ZONE &&
 	    type >= SCOUTFS_INODE_INDEX_META_SEQ_TYPE  &&
@@ -254,34 +218,13 @@ static print_func_t find_printer(u8 zone, u8 type, bool *suppress)
 
 	if (zone == SCOUTFS_FS_ZONE) {
 		switch(type) {
-			case SCOUTFS_INODE_TYPE:
-				if (!print_args.print_inodes)
-					*suppress = true;
-				return print_inode;
-			case SCOUTFS_XATTR_TYPE:
-				if (!print_args.print_xattrs)
-					*suppress = true;
-				return print_xattr;
-			case SCOUTFS_DIRENT_TYPE:
-				if (!print_args.print_dirents)
-					*suppress = true;
-				return print_dirent;
-			case SCOUTFS_READDIR_TYPE:
-				if (!print_args.print_dirents)
-					*suppress = true;
-				return print_dirent;
-			case SCOUTFS_SYMLINK_TYPE:
-				if (!print_args.print_symlinks)
-					*suppress = true;
-				return print_symlink;
-			case SCOUTFS_LINK_BACKREF_TYPE:
-				if (!print_args.print_backrefs)
-					*suppress = true;
-				return print_dirent;
-			case SCOUTFS_DATA_EXTENT_TYPE:
-				if (!print_args.print_extents)
-					*suppress = true;
-				return print_data_extent;
+			case SCOUTFS_INODE_TYPE: return print_inode;
+			case SCOUTFS_XATTR_TYPE: return print_xattr;
+			case SCOUTFS_DIRENT_TYPE: return print_dirent;
+			case SCOUTFS_READDIR_TYPE: return print_dirent;
+			case SCOUTFS_SYMLINK_TYPE: return print_symlink;
+			case SCOUTFS_LINK_BACKREF_TYPE: return print_dirent;
+			case SCOUTFS_DATA_EXTENT_TYPE: return print_data_extent;
 		}
 	}
 
@@ -301,16 +244,12 @@ static int print_fs_item(struct scoutfs_key *key, u64 seq, u8 flags, void *val,
 
 	/* only items in leaf blocks have values */
 	if (val != NULL && !(flags & SCOUTFS_ITEM_FLAG_DELETION)) {
-		bool suppress = false;
-
-		printer = find_printer(key->sk_zone, key->sk_type, &suppress);
-		if (printer) {
-			if (!suppress)
-				printer(key, val, val_len);
-		} else {
+		printer = find_printer(key->sk_zone, key->sk_type);
+		if (printer)
+			printer(key, val, val_len);
+		else
 			printf("      (unknown zone %u type %u)\n",
 			       key->sk_zone, key->sk_type);
-		}
 	}
 
 	return 0;
@@ -1098,7 +1037,12 @@ static void print_super_block(struct scoutfs_super_block *super, u64 blkno)
 	}
 }
 
-static int print_volume(int fd)
+struct print_args {
+	char *meta_device;
+	bool skip_likely_huge;
+};
+
+static int print_volume(int fd, struct print_args *args)
 {
 	struct scoutfs_super_block *super = NULL;
 	struct print_recursion_args pa;
@@ -1148,7 +1092,7 @@ static int print_volume(int fd)
 			ret = err;
 	}
 
-	if (print_args.walk_allocs) {
+	if (!args->skip_likely_huge) {
 		for (i = 0; i < array_size(super->meta_alloc); i++) {
 			snprintf(str, sizeof(str), "meta_alloc[%u]", i);
 			err = print_btree(fd, super, str, &super->meta_alloc[i].root,
@@ -1175,21 +1119,18 @@ static int print_volume(int fd)
 
 	pa.super = super;
 	pa.fd = fd;
-	if (print_args.walk_srch_root) {
+	if (!args->skip_likely_huge) {
 		err = print_btree_leaf_items(fd, super, &super->srch_root.ref,
 					     print_srch_root_files, &pa);
 		if (err && !ret)
 			ret = err;
 	}
+	err = print_btree_leaf_items(fd, super, &super->logs_root.ref,
+				     print_log_trees_roots, &pa);
+	if (err && !ret)
+		ret = err;
 
-	if (print_args.walk_logs_root) {
-		err = print_btree_leaf_items(fd, super, &super->logs_root.ref,
-					     print_log_trees_roots, &pa);
-		if (err && !ret)
-			ret = err;
-	}
-
-	if (print_args.walk_fs_root) {
+	if (!args->skip_likely_huge) {
 		err = print_btree(fd, super, "fs_root", &super->fs_root,
 				  print_fs_item, NULL);
 		if (err && !ret)
@@ -1202,16 +1143,16 @@ out:
 	return ret;
 }
 
-static int do_print(void)
+static int do_print(struct print_args *args)
 {
 	int ret;
 	int fd;
 
-	fd = open(print_args.meta_device, O_RDONLY);
+	fd = open(args->meta_device, O_RDONLY);
 	if (fd < 0) {
 		ret = -errno;
 		fprintf(stderr, "failed to open '%s': %s (%d)\n",
-			print_args.meta_device, strerror(errno), errno);
+			args->meta_device, strerror(errno), errno);
 		return ret;
 	}
 
@@ -1219,169 +1160,30 @@ static int do_print(void)
 	if (ret < 0)
 		goto out;
 
-	ret = print_volume(fd);
+	ret = print_volume(fd, args);
 out:
 	close(fd);
 	return ret;
 };
 
-enum {
-	LOGS_OPT = 0,
-	FS_OPT,
-	SRCH_OPT
-};
-
-static char *const root_tokens[] = {
-	[LOGS_OPT] = "logs",
-	[FS_OPT] =   "fs",
-	[SRCH_OPT] = "srch",
-	NULL
-};
-
-enum {
-	INODE_OPT = 0,
-	XATTR_OPT,
-	DIRENT_OPT,
-	SYMLINK_OPT,
-	BACKREF_OPT,
-	EXTENT_OPT
-};
-
-static char *const item_tokens[] = {
-	[INODE_OPT] =   "inode",
-	[XATTR_OPT] =   "xattr",
-	[DIRENT_OPT] =  "dirent",
-	[SYMLINK_OPT] = "symlink",
-	[BACKREF_OPT] = "backref",
-	[EXTENT_OPT] =  "extent",
-	NULL
-};
-
-static void clear_items(void)
-{
-	print_args.print_inodes = false;
-	print_args.print_xattrs = false;
-	print_args.print_dirents = false;
-	print_args.print_symlinks = false;
-	print_args.print_backrefs = false;
-	print_args.print_extents = false;
-}
-
-static void clear_roots(void)
-{
-	print_args.walk_logs_root = false;
-	print_args.walk_fs_root = false;
-	print_args.walk_srch_root = false;
-}
-
 static int parse_opt(int key, char *arg, struct argp_state *state)
 {
 	struct print_args *args = state->input;
-	char *subopts;
-	char *value;
-	bool parse_err = false;
 
 	switch (key) {
 	case 'S':
 		args->skip_likely_huge = true;
 		break;
-
-	case 'a':
-		args->allocs_requested = true;
-		args->walk_allocs = true;
-		break;
-
-	case 'i':
-		/* Specific items being requested- clear them all to start */
-		if (!args->items_requested) {
-			clear_items();
-			if (!args->allocs_requested)
-				args->walk_allocs = false;
-			args->items_requested = true;
-		}
-
-		subopts = arg;
-		while (*subopts != '\0' && !parse_err) {
-			switch (getsubopt(&subopts, item_tokens, &value)) {
-			case INODE_OPT:
-				args->print_inodes = true;
-				break;
-			case XATTR_OPT:
-				args->print_xattrs = true;
-				break;
-			case DIRENT_OPT:
-				args->print_dirents = true;
-				break;
-			case SYMLINK_OPT:
-				args->print_symlinks = true;
-				break;
-			case BACKREF_OPT:
-				args->print_backrefs = true;
-				break;
-			case EXTENT_OPT:
-				args->print_extents = true;
-				break;
-			default:
-				argp_usage(state);
-				parse_err = true;
-				break;
-			}
-		}
-		break;
-
-	case 'r':
-		/* Specific roots being requested- clear them all to start */
-		if (!args->roots_requested) {
-			clear_roots();
-			if (!args->allocs_requested)
-				args->walk_allocs = false;
-			args->roots_requested = true;
-		}
-
-		subopts = arg;
-		while (*subopts != '\0' && !parse_err) {
-			switch (getsubopt(&subopts, root_tokens, &value)) {
-			case LOGS_OPT:
-				args->walk_logs_root = true;
-				break;
-			case FS_OPT:
-				args->walk_fs_root = true;
-				break;
-			case SRCH_OPT:
-				args->walk_srch_root = true;
-				break;
-			default:
-				argp_usage(state);
-				parse_err = true;
-				break;
-			}
-		}
-		break;
-
 	case ARGP_KEY_ARG:
 		if (!args->meta_device)
 			args->meta_device = strdup_or_error(state, arg);
 		else
 			argp_error(state, "more than one argument given");
 		break;
-
 	case ARGP_KEY_FINI:
 		if (!args->meta_device)
 			argp_error(state, "no metadata device argument given");
-
-		/*
-		 * For backwards compatibility, translate -S. Should we warn if
-		 * this conflicts with other explicit options?
-		 */
-		if (args->skip_likely_huge) {
-			if (!args->allocs_requested)
-				args->walk_allocs = false;
-			args->walk_fs_root = false;
-			args->walk_srch_root = false;
-		}
-
 		break;
-
 	default:
 		break;
 	}
@@ -1390,10 +1192,7 @@ static int parse_opt(int key, char *arg, struct argp_state *state)
 }
 
 static struct argp_option options[] = {
-	{ "allocs", 'a', NULL, 0, "Print metadata and data alloc lists" },
-	{ "items", 'i', "ITEMS", 0, "Item(s) to print (inode, xattr, dirent, symlink, backref, extent)" },
-	{ "roots", 'r', "ROOTS", 0, "Tree root(s) to walk (logs, srch, fs)" },
-	{ "skip-likely-huge", 'S', NULL, 0, "Skip allocs, srch root and fs root to minimize output size" },
+	{ "skip-likely-huge", 'S', NULL, 0, "Skip large structures to minimize output size"},
 	{ NULL }
 };
 
@@ -1406,15 +1205,17 @@ static struct argp argp = {
 
 static int print_cmd(int argc, char **argv)
 {
+	struct print_args print_args = {NULL};
 	int ret;
 
 	ret = argp_parse(&argp, argc, argv, 0, NULL, &print_args);
 	if (ret)
 		return ret;
 
-	return do_print();
+	return do_print(&print_args);
 }
 
+
 static void __attribute__((constructor)) print_ctor(void)
 {
 	cmd_register_argp("print", &argp, GROUP_DEBUG, print_cmd);