Don't overrun the block budget in server_log_merge_free_work().

This fixes a potential fence post failure like the following:

error: 1 holders exceeded alloc budget av: bef 7407 now 7392, fr: bef 8185 now 7672

The code is only accounting for the freed btree blocks, not the dirtying of
other items. So it's possible to be at exactly (COMMIT_HOLD_ALLOC_BUDGET / 2),
dirty some log btree blocks, loop again, then consume another
(COMMIT_HOLD_ALLOC_BUDGET / 2) and blow past the total budget.

In this example, we went over by 13 blocks.

By only consuming up to 1/8 of the budget on each loop, and committing when we
have consumed 3/4 of the budget, we can avoid the fence post condition.

Signed-off-by: Chris Kirby <ckirby@versity.com>

kmod/src/server.c

@@ -1299,12 +1299,10 @@ static int finalize_and_start_log_merge(struct super_block *sb, struct scoutfs_l
  * is nested inside holding commits so we recheck the persistent item
  * each time we commit to make sure it's still what we think.   The
  * caller is still going to send the item to the client so we update the
- * caller's each time we make progress.  This is a best-effort attempt
- * to clean up and it's valid to leave extents in data_freed we don't
- * return errors to the caller.  The client will continue the work later
- * in get_log_trees or as the rid is reclaimed.
+ * caller's each time we make progress.  If we hit an error applying the
+ * changes we make then we can't send the log_trees to the client.
  */
-static void try_drain_data_freed(struct super_block *sb, struct scoutfs_log_trees *lt)
+static int try_drain_data_freed(struct super_block *sb, struct scoutfs_log_trees *lt)
 {
 	DECLARE_SERVER_INFO(sb, server);
 	struct scoutfs_super_block *super = DIRTY_SUPER_SB(sb);
@@ -1313,6 +1311,7 @@ static void try_drain_data_freed(struct super_block *sb, struct scoutfs_log_tree
 	struct scoutfs_log_trees drain;
 	struct scoutfs_key key;
 	COMMIT_HOLD(hold);
+	bool apply = false;
 	int ret = 0;
 	int err;
 
@@ -1321,22 +1320,27 @@ static void try_drain_data_freed(struct super_block *sb, struct scoutfs_log_tree
 	while (lt->data_freed.total_len != 0) {
 		server_hold_commit(sb, &hold);
 		mutex_lock(&server->logs_mutex);
+		apply = true;
 
 		ret = find_log_trees_item(sb, &super->logs_root, false, rid, U64_MAX, &drain);
-		if (ret < 0)
+		if (ret < 0) {
+			ret = 0;
 			break;
+		}
 
 		/* careful to only keep draining the caller's specific open trans */
 		if (drain.nr != lt->nr || drain.get_trans_seq != lt->get_trans_seq ||
 		    drain.commit_trans_seq != lt->commit_trans_seq || drain.flags != lt->flags) {
-			ret = -ENOENT;
+			ret = 0;
 			break;
 		}
 
 		ret = scoutfs_btree_dirty(sb, &server->alloc, &server->wri,
 					  &super->logs_root, &key);
-		if (ret < 0)
+		if (ret < 0) {
+			ret = 0;
 			break;
+		}
 
 		/* moving can modify and return errors, always update caller and item */
 		mutex_lock(&server->alloc_mutex);
@@ -1352,19 +1356,19 @@ static void try_drain_data_freed(struct super_block *sb, struct scoutfs_log_tree
 		BUG_ON(err < 0); /* dirtying must guarantee success */
 
 		mutex_unlock(&server->logs_mutex);
-
 		ret = server_apply_commit(sb, &hold, ret);
-		if (ret < 0) {
-			ret = 0; /* don't try to abort, ignoring ret */
+		apply = false;
+
+		if (ret < 0)
 			break;
-		}
 	}
 
-	/* try to cleanly abort and write any partial dirty btree blocks, but ignore result */
-	if (ret < 0) {
+	if (apply) {
 		mutex_unlock(&server->logs_mutex);
-		server_apply_commit(sb, &hold, 0);
+		server_apply_commit(sb, &hold, ret);
 	}
+
+	return ret;
 }
 
 /*
@@ -1572,9 +1576,9 @@ out:
 		scoutfs_err(sb, "error %d getting log trees for rid %016llx: %s",
 			    ret, rid, err_str);
 
-	/* try to drain excessive data_freed with additional commits, if needed, ignoring err */
+	/* try to drain excessive data_freed with additional commits, if needed */
 	if (ret == 0)
-		try_drain_data_freed(sb, &lt);
+		ret = try_drain_data_freed(sb, &lt);
 
 	return scoutfs_net_response(sb, conn, cmd, id, ret, &lt, sizeof(lt));
 }
@@ -2527,7 +2531,7 @@ static void server_log_merge_free_work(struct work_struct *work)
 
 		ret = scoutfs_btree_free_blocks(sb, &server->alloc,
 						&server->wri, &fr.key,
-						&fr.root, COMMIT_HOLD_ALLOC_BUDGET / 2);
+						&fr.root, COMMIT_HOLD_ALLOC_BUDGET / 8);
 		if (ret < 0) {
 			err_str = "freeing log btree";
 			break;
@@ -2546,7 +2550,7 @@ static void server_log_merge_free_work(struct work_struct *work)
 		/* freed blocks are in allocator, we *have* to update fr */
 		BUG_ON(ret < 0);
 
-		if (server_hold_alloc_used_since(sb, &hold) >= COMMIT_HOLD_ALLOC_BUDGET / 2) {
+		if (server_hold_alloc_used_since(sb, &hold) >= (COMMIT_HOLD_ALLOC_BUDGET * 3) / 4) {
 			mutex_unlock(&server->logs_mutex);
 			ret = server_apply_commit(sb, &hold, ret);
 			commit = false;
@@ -4149,7 +4153,7 @@ static void fence_pending_recov_worker(struct work_struct *work)
 	struct server_info *server = container_of(work, struct server_info,
 						  fence_pending_recov_work);
 	struct super_block *sb = server->sb;
-	union scoutfs_inet_addr addr;
+	union scoutfs_inet_addr addr = {{0,}};
 	u64 rid = 0;
 	int ret = 0;
 

kmod/src/trans.c

@@ -159,6 +159,58 @@ static bool drained_holders(struct trans_info *tri)
 	return holders == 0;
 }
 
+static int commit_current_log_trees(struct super_block *sb, char **str)
+{
+	DECLARE_TRANS_INFO(sb, tri);
+
+	return (*str = "data submit", scoutfs_inode_walk_writeback(sb, true)) ?:
+	       (*str = "item dirty", scoutfs_item_write_dirty(sb))  ?:
+	       (*str = "data prepare", scoutfs_data_prepare_commit(sb))  ?:
+	       (*str = "alloc prepare", scoutfs_alloc_prepare_commit(sb, &tri->alloc, &tri->wri)) ?:
+	       (*str = "meta write", scoutfs_block_writer_write(sb, &tri->wri))  ?:
+	       (*str = "data wait", scoutfs_inode_walk_writeback(sb, false)) ?:
+	       (*str = "commit log trees", commit_btrees(sb)) ?:
+	       scoutfs_item_write_done(sb);
+}
+
+static int get_next_log_trees(struct super_block *sb, char **str)
+{
+	return (*str = "get log trees", scoutfs_trans_get_log_trees(sb));
+}
+
+static int retry_forever(struct super_block *sb, int (*func)(struct super_block *sb, char **str))
+{
+	bool retrying = false;
+	char *str;
+	int ret;
+
+	do {
+		str = NULL;
+
+		ret = func(sb, &str);
+		if (ret < 0) {
+			if (!retrying) {
+				scoutfs_warn(sb, "critical transaction commit failure: %s = %d, retrying",
+					    str, ret);
+				retrying = true;
+			}
+
+			if (scoutfs_forcing_unmount(sb)) {
+				ret = -EIO;
+				break;
+			}
+
+			msleep(2 * MSEC_PER_SEC);
+
+		} else if (retrying) {
+			scoutfs_info(sb, "retried transaction commit succeeded");
+		}
+
+	} while (ret < 0);
+
+	return ret;
+}
+
 /*
  * This work func is responsible for writing out all the dirty blocks
  * that make up the current dirty transaction.  It prevents writers from
@@ -184,8 +236,6 @@ void scoutfs_trans_write_func(struct work_struct *work)
 	struct trans_info *tri = container_of(work, struct trans_info, write_work.work);
 	struct super_block *sb = tri->sb;
 	struct scoutfs_sb_info *sbi = SCOUTFS_SB(sb);
-	bool retrying = false;
-	char *s = NULL;
 	int ret = 0;
 
 	tri->task = current;
@@ -214,37 +264,9 @@ void scoutfs_trans_write_func(struct work_struct *work)
 
 	scoutfs_inc_counter(sb, trans_commit_written);
 
-	do {
-		ret = (s = "data submit", scoutfs_inode_walk_writeback(sb, true)) ?:
-		      (s = "item dirty", scoutfs_item_write_dirty(sb))  ?:
-		      (s = "data prepare", scoutfs_data_prepare_commit(sb))  ?:
-		      (s = "alloc prepare", scoutfs_alloc_prepare_commit(sb, &tri->alloc,
-									 &tri->wri))  ?:
-		      (s = "meta write", scoutfs_block_writer_write(sb, &tri->wri))  ?:
-		      (s = "data wait", scoutfs_inode_walk_writeback(sb, false)) ?:
-		      (s = "commit log trees", commit_btrees(sb)) ?:
-		      scoutfs_item_write_done(sb) ?:
-		      (s = "get log trees", scoutfs_trans_get_log_trees(sb));
-		if (ret < 0) {
-			if (!retrying) {
-				scoutfs_warn(sb, "critical transaction commit failure: %s = %d, retrying",
-					    s, ret);
-				retrying = true;
-			}
-
-			if (scoutfs_forcing_unmount(sb)) {
-				ret = -EIO;
-				break;
-			}
-
-			msleep(2 * MSEC_PER_SEC);
-
-		} else if (retrying) {
-			scoutfs_info(sb, "retried transaction commit succeeded");
-		}
-
-	} while (ret < 0);
-
+	/* retry {commit,get}_log_trees until they succeeed, can only fail when forcing unmount */
+	ret = retry_forever(sb, commit_current_log_trees) ?:
+	      retry_forever(sb, get_next_log_trees);
 out:
 	spin_lock(&tri->write_lock);
 	tri->write_count++;

tests/funcs/exec.sh

@@ -80,3 +80,15 @@ t_compare_output()
 {
 	"$@" >&7 2>&1
 }
+
+#
+# usually bash prints an annoying output message when jobs
+# are killed.  We can avoid that by redirecting stderr for
+# the bash process when it reaps the jobs that are killed.
+#
+t_silent_kill() {
+	exec {ERR}>&2 2>/dev/null
+	kill "$@"
+	wait "$@"
+	exec 2>&$ERR {ERR}>&-
+}

tests/funcs/filter.sh

@@ -160,6 +160,9 @@ t_filter_dmesg()
 	re="$re|Pipe handler or fully qualified core dump path required.*"
 	re="$re|Set kernel.core_pattern before fs.suid_dumpable.*"
 
+	# perf warning that it adjusted sample rate
+	re="$re|perf: interrupt took too long.*lowering kernel.perf_event_max_sample_rate.*"
+
 	egrep -v "($re)" | \
 		ignore_harmless_unwind_kasan_stack_oob
 }

tests/funcs/tap.sh

@@ -0,0 +1,88 @@
+
+#
+# Generate TAP format test results
+#
+
+t_tap_header()
+{
+	local runid=$1
+	local sequence=( $(echo $tests) )
+	local count=${#sequence[@]}
+
+	# avoid recreating the same TAP result over again - harness sets this
+	[[ -z "$runid" ]] && runid="*test*"
+
+	cat > $T_RESULTS/scoutfs.tap <<TAPEOF
+TAP version 14
+1..${count}
+#
+# TAP results for run ${runid}
+#
+# host/run info:
+#
+#   hostname: ${HOSTNAME}
+#   test start time: $(date --utc)
+#   uname -r: $(uname -r)
+#   scoutfs commit id: $(git describe --tags)
+#
+# sequence for this run:
+#
+TAPEOF
+
+	# Sequence
+	for t in ${tests}; do
+		 echo ${t/.sh/}
+	done | cat -n | expand | column -c 120 | expand | sed 's/^ /#/' >> $T_RESULTS/scoutfs.tap
+	echo "#" >> $T_RESULTS/scoutfs.tap
+}
+
+t_tap_progress()
+{
+(
+	local i=$(( testcount + 1 ))
+	local testname=$1
+	local result=$2
+
+	local diff=""
+	local dmsg=""
+
+	if [[ -s "$T_RESULTS/tmp/${testname}/dmesg.new" ]]; then
+		dmsg="1"
+	fi
+
+	if ! cmp -s golden/${testname} $T_RESULTS/output/${testname}; then
+		diff="1"
+	fi
+
+	if [[ "${result}" == "100" ]] && [[ -z "${dmsg}" ]] && [[ -z "${diff}" ]]; then
+		echo "ok ${i} - ${testname}"
+	elif [[ "${result}" == "103" ]]; then
+		echo "ok ${i} - ${testname}"
+		echo "# ${testname} ** skipped - permitted **"
+	else
+		echo "not ok ${i} - ${testname}"
+		case ${result} in
+		101)
+			echo "# ${testname} ** skipped **"
+			;;
+		102)
+			echo "# ${testname} ** failed **"
+			;;
+		esac
+
+		if [[ -n "${diff}" ]]; then
+			echo "#"
+			echo "# diff:"
+			echo "#"
+			diff -u golden/${testname} $T_RESULTS/output/${testname} | expand | sed 's/^/#   /'
+		fi
+
+		if [[ -n "${dmsg}" ]]; then
+			echo "#"
+			echo "# dmesg:"
+			echo "#"
+			cat "$T_RESULTS/tmp/${testname}/dmesg.new" | sed 's/^/#   /'
+		fi
+	fi
+) >> $T_RESULTS/scoutfs.tap
+}

tests/run-tests.sh

@@ -512,6 +512,11 @@ msg "running tests"
 > "$T_RESULTS/skip.log"
 > "$T_RESULTS/fail.log"
 
+# generate a test ID to make sure we can de-duplicate TAP results in aggregation
+. funcs/tap.sh
+t_tap_header $(uuidgen)
+
+testcount=0
 passed=0
 skipped=0
 failed=0
@@ -527,12 +532,15 @@ for t in $tests; do
 	cmd rm -rf "$T_TMPDIR"
 	cmd mkdir -p "$T_TMPDIR"
 
-	# create a test name dir in the fs
+	# create a test name dir in the fs, clean up old data as needed
 	T_DS=""
 	for i in $(seq 0 $((T_NR_MOUNTS - 1))); do
 		dir="${T_M[$i]}/test/$test_name"
 
-		test $i == 0 && cmd mkdir -p "$dir"
+		test $i == 0 && (
+			test -d "$dir" && cmd rm -rf "$dir"
+			cmd mkdir -p "$dir"
+		)
 
 		eval T_D$i=$dir
 		T_D[$i]=$dir
@@ -637,6 +645,11 @@ for t in $tests; do
 
 		test -n "$T_ABORT" && die "aborting after first failure"
 	fi
+
+	# record results for TAP format output
+	t_tap_progress $test_name $sts
+	((testcount++))
+
 done
 
 msg "all tests run: $passed passed, $skipped skipped, $skipped_permitted skipped (permitted), $failed failed"

tests/tests/basic-truncate.sh

@@ -11,7 +11,7 @@ FILE="$T_D0/file"
 # final block as we truncated past it.
 #
 echo "== truncate writes zeroed partial end of file block"
-yes | dd of="$FILE" bs=8K count=1 status=none iflag=fullblock
+yes 2>/dev/null | dd of="$FILE" bs=8K count=1 status=none iflag=fullblock
 sync
 
 # not passing iflag=fullblock causes the file occasionally to just be

tests/tests/enospc.sh

@@ -88,6 +88,11 @@ rm -rf "$SCR/xattrs"
 
 echo "== make sure we can create again"
 file="$SCR/file-after"
+C=120
+while (( C-- )); do
+	touch $file 2> /dev/null && break
+	sleep 1
+done
 touch $file
 setfattr -n user.scoutfs-enospc -v 1 "$file"
 sync

tests/tests/lock-recover-invalidate.sh

@@ -38,6 +38,6 @@ while [ "$SECONDS" -lt "$END" ]; do
 done
 
 echo "== stopping background load"
-kill $load_pids
+t_silent_kill $load_pids
 
 t_pass

tests/tests/orphan-inodes.sh

@@ -5,18 +5,6 @@
 t_require_commands sleep touch sync stat handle_cat kill rm
 t_require_mounts 2
 
-#
-# usually bash prints an annoying output message when jobs
-# are killed.  We can avoid that by redirecting stderr for
-# the bash process when it reaps the jobs that are killed.
-#
-silent_kill() {
-	exec {ERR}>&2 2>/dev/null
-	kill "$@"
-	wait "$@"
-	exec 2>&$ERR {ERR}>&-
-}
-
 #
 # We don't have a great way to test that inode items still exist.   We
 # don't prevent opening handles with nlink 0 today, so we'll use that.
@@ -52,7 +40,7 @@ inode_exists $ino || echo "$ino didn't exist"
 
 echo "== orphan from failed evict deletion is picked up"
 # pending kill signal stops evict from getting locks and deleting
-silent_kill $pid
+t_silent_kill $pid
 t_set_sysfs_mount_option 0 orphan_scan_delay_ms 1000
 sleep 5
 inode_exists $ino && echo "$ino still exists"
@@ -70,7 +58,7 @@ for nr in $(t_fs_nrs); do
 	rm -f "$path"
 done
 sync
-silent_kill $pids
+t_silent_kill $pids
 for nr in $(t_fs_nrs); do
 	t_force_umount $nr
 done
@@ -82,7 +70,15 @@ done
 # wait for orphan scans to run
 t_set_all_sysfs_mount_options orphan_scan_delay_ms 1000
 # also have to wait for delayed log merge work from mount
-sleep 15
+C=120
+while (( C-- )); do
+	brk=1
+	for ino in $inos; do
+		inode_exists $ino && brk=0
+	done
+	test $brk -eq 1 && break
+	sleep 1
+done
 for ino in $inos; do
 	inode_exists $ino && echo "$ino still exists"
 done
@@ -131,7 +127,7 @@ while [ $SECONDS -lt $END ]; do
 	done
 
 	# trigger eviction deletion of each file in each mount
-	silent_kill $pids
+	t_silent_kill $pids
 
 	wait || t_fail "handle_fsetxattr failed"