grab traces at exit

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

kmod/src/scoutfs_trace.h

@@ -2642,24 +2642,39 @@ TRACE_EVENT(scoutfs_block_dirty_ref,
 );
 
 TRACE_EVENT(scoutfs_get_file_block,
-	TP_PROTO(struct super_block *sb, u64 blkno, int flags),
+	TP_PROTO(struct super_block *sb, u64 blkno, int flags,
+		 struct scoutfs_srch_block *srb),
 
-	TP_ARGS(sb, blkno, flags),
+	TP_ARGS(sb, blkno, flags, srb),
 
 	TP_STRUCT__entry(
 		SCSB_TRACE_FIELDS
 		__field(__u64, blkno)
 		__field(int, flags)
+		__field(__u64, first_hash)
+		__field(__u64, first_ino)
+		__field(__u64, first_id)
+		__field(__u64, last_hash)
+		__field(__u64, last_ino)
+		__field(__u64, last_id)
 	),
 
 	TP_fast_assign(
 		SCSB_TRACE_ASSIGN(sb);
 		__entry->blkno = blkno;
 		__entry->flags = flags;
+		__entry->first_hash = __le64_to_cpu(srb->first.hash);
+		__entry->first_ino = __le64_to_cpu(srb->first.ino);
+		__entry->first_id = __le64_to_cpu(srb->first.id);
+		__entry->last_hash = __le64_to_cpu(srb->last.hash);
+		__entry->last_ino = __le64_to_cpu(srb->last.ino);
+		__entry->last_id = __le64_to_cpu(srb->last.id);
 	),
 
-	TP_printk(SCSBF" blkno %llu flags 0x%x",
-		  SCSB_TRACE_ARGS, __entry->blkno, __entry->flags)
+	TP_printk(SCSBF" blkno %llu flags 0x%x first_hash 0x%llx first_ino %llu fist_id 0x%llx last_hash 0x%llx last_ino %llu last_id 0x%llx",
+		  SCSB_TRACE_ARGS, __entry->blkno, __entry->flags,
+		  __entry->first_hash, __entry->first_ino, __entry->first_id,
+		  __entry->last_hash, __entry->last_ino, __entry->last_id)
 );
 
 TRACE_EVENT(scoutfs_block_stale,

kmod/src/srch.c

@@ -443,7 +443,7 @@ out:
 		sfl->blocks = cpu_to_le64(blk + 1);
 
 	if (bl) {
-		trace_scoutfs_get_file_block(sb, bl->blkno, flags);
+		trace_scoutfs_get_file_block(sb, bl->blkno, flags, bl->data);
 	}
 
 	*bl_ret = bl;
@@ -2293,8 +2293,10 @@ static void scoutfs_srch_compact_worker(struct work_struct *work)
 out:
 	/* our allocators and files should be stable */
 	WARN_ON_ONCE(ret == -ESTALE);
-	if (ret < 0)
+	if (ret < 0) {
+		scoutfs_err(sb, "@@@ srch_compact_error %d", ret);
 		scoutfs_inc_counter(sb, srch_compact_error);
+	}
 
 	scoutfs_block_writer_forget_all(sb, &wri);
 	queue_compact_work(srinf, sc != NULL && sc->nr > 0 && ret == 0);

tests/golden/srch-safe-merge-pos

@@ -1,37 +1,7 @@
 == initialize per-mount values
 == arm compaction triggers
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_merge_stop_safe armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_merge_stop_safe armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_merge_stop_safe armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_merge_stop_safe armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_merge_stop_safe armed: 1
 == compact more often
 == create padded sorted inputs by forcing log rotation
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_force_log_rotate armed: 1
-trigger srch_compact_logs_pad_safe armed: 1
 == compaction of padded should stop at safe
 == verify no compaction errors
 == cleanup

tests/run-tests.sh

@@ -137,6 +137,9 @@ while true; do
 	        test -n "$2" || die "-l must have a nr iterations argument"
 		test "$2" -eq "$2" 2>/dev/null || die "-l <nr> argument must be an integer"
 		T_LOOP_ITER="$2"
+
+		# when looping, break after first failure
+		T_ABORT="1"
 		shift
 		;;
 	-M)
@@ -399,31 +402,44 @@ if [ -n "$T_INSMOD" ]; then
 	cmd insmod "$T_MODULE"
 fi
 
-if [ -n "$T_TRACE_MULT" ]; then
-#	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
-fi
+start_tracing() {
+	if [ -n "$T_TRACE_MULT" ]; then
+		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
+	fi
 
-nr_globs=${#T_TRACE_GLOB[@]}
-if [ $nr_globs -gt 0 ]; then
-	echo 0 > /sys/kernel/debug/tracing/events/scoutfs/enable
+	nr_globs=${#T_TRACE_GLOB[@]}
+	if [ $nr_globs -gt 0 ]; then
+		echo 0 > /sys/kernel/debug/tracing/events/scoutfs/enable
 
-	for g in "${T_TRACE_GLOB[@]}"; do
-		for e in /sys/kernel/debug/tracing/events/scoutfs/$g/enable; do
-			if test -w "$e"; then
-				echo 1 > "$e"
-			else
-				die "-t glob '$g' matched no scoutfs events"
-			fi
+		for g in "${T_TRACE_GLOB[@]}"; do
+			for e in /sys/kernel/debug/tracing/events/scoutfs/$g/enable; do
+				if test -w "$e"; then
+					echo 1 > "$e"
+				else
+					die "-t glob '$g' matched no scoutfs events"
+				fi
+			done
 		done
-	done
 
-	nr_events=$(cat /sys/kernel/debug/tracing/set_event | wc -l)
-	msg "enabled $nr_events trace events from $nr_globs -t globs"
-fi
+		nr_events=$(cat /sys/kernel/debug/tracing/set_event | wc -l)
+		msg "enabled $nr_events trace events from $nr_globs -t globs"
+	fi
+}
+
+stop_tracing() {
+	if [ -n "$T_TRACE_GLOB" -o -n "$T_TRACE_PRINTK" ]; then
+		msg "saving traces and disabling tracing"
+		echo 0 > /sys/kernel/debug/tracing/events/scoutfs/enable
+		echo 0 > /sys/kernel/debug/tracing/options/trace_printk
+		cat /sys/kernel/debug/tracing/trace | gzip > "$T_RESULTS/traces.gz"
+		if [ -n "$orig_trace_size" ]; then
+			echo $orig_trace_size > /sys/kernel/debug/tracing/buffer_size_kb
+		fi
+	fi
+}
 
 if [ -n "$T_TRACE_PRINTK" ]; then
 	echo "$T_TRACE_PRINTK" > /sys/kernel/debug/tracing/options/trace_printk
@@ -600,24 +616,26 @@ passed=0
 skipped=0
 failed=0
 skipped_permitted=0
-for t in $tests; do
-	# tests has basenames from sequence, get path and name
-	t="tests/$t"
-	test_name=$(basename "$t" | sed -e 's/.sh$//')
+for iter in $(seq 1 $T_LOOP_ITER); do
 
-	# get stats from previous pass
-	last="$T_RESULTS/last-passed-test-stats"
-	stats=$(grep -s "^$test_name " "$last" | cut -d " " -f 2-)
-	test -n "$stats" && stats="last: $stats"
-	printf "  %-30s $stats" "$test_name"
+	start_tracing
 
-	# mark in dmesg as to what test we are running
-	echo "run scoutfs test $test_name" > /dev/kmsg
+	for t in $tests; do
+		# tests has basenames from sequence, get path and name
+		t="tests/$t"
+		test_name=$(basename "$t" | sed -e 's/.sh$//')
 
-	# let the test get at its extra files
-	T_EXTRA="$T_TESTS/extra/$test_name"
+		# get stats from previous pass
+		last="$T_RESULTS/last-passed-test-stats"
+		stats=$(grep -s "^$test_name " "$last" | cut -d " " -f 2-)
+		test -n "$stats" && stats="last: $stats"
+		printf "  %-30s $stats" "$test_name"
 
-	for iter in $(seq 1 $T_LOOP_ITER); do
+		# mark in dmesg as to what test we are running
+		echo "run scoutfs test $test_name" > /dev/kmsg
+
+		# let the test get at its extra files
+		T_EXTRA="$T_TESTS/extra/$test_name"
 
 		# create a temporary dir and file path for the test
 		T_TMPDIR="$T_RESULTS/tmp/$test_name"
@@ -704,55 +722,43 @@ for t in $tests; do
 			sts=$T_FAIL_STATUS
 		fi
 
-		# stop looping if we didn't pass
-		if [ "$sts" != "$T_PASS_STATUS" ]; then
-			break;
+		# show and record the result of the test
+		if [ "$sts" == "$T_PASS_STATUS" ]; then
+			echo "  passed: $stats"
+			((passed++))
+			# save stats for passed test
+			grep -s -v "^$test_name " "$last" > "$last.tmp"
+			echo "$test_name $stats" >> "$last.tmp"
+			mv -f "$last.tmp" "$last"
+		elif [ "$sts" == "$T_SKIP_PERMITTED_STATUS" ]; then
+			echo "  [ skipped (permitted): $message ]"
+			echo "$test_name skipped (permitted) $message " >> "$T_RESULTS/skip.log"
+			((skipped_permitted++))
+		elif [ "$sts" == "$T_SKIP_STATUS" ]; then
+			echo "  [ skipped: $message ]"
+			echo "$test_name $message" >> "$T_RESULTS/skip.log"
+			((skipped++))
+		elif [ "$sts" == "$T_FAIL_STATUS" ]; then
+			echo "  [ failed: $message ]"
+			echo "$test_name $message" >> "$T_RESULTS/fail.log"
+			((failed++))
+
+			if [ -n "$T_ABORT" ]; then
+				stop_tracing
+				die "aborting after first failure"
+			fi
 		fi
+
+		# record results for TAP format output
+		t_tap_progress $test_name $sts
+		((testcount++))
 	done
 
-	# show and record the result of the test
-	if [ "$sts" == "$T_PASS_STATUS" ]; then
-		echo "  passed: $stats"
-		((passed++))
-		# save stats for passed test
-		grep -s -v "^$test_name " "$last" > "$last.tmp"
-		echo "$test_name $stats" >> "$last.tmp"
-		mv -f "$last.tmp" "$last"
-	elif [ "$sts" == "$T_SKIP_PERMITTED_STATUS" ]; then
-		echo "  [ skipped (permitted): $message ]"
-		echo "$test_name skipped (permitted) $message " >> "$T_RESULTS/skip.log"
-		((skipped_permitted++))
-	elif [ "$sts" == "$T_SKIP_STATUS" ]; then
-		echo "  [ skipped: $message ]"
-		echo "$test_name $message" >> "$T_RESULTS/skip.log"
-		((skipped++))
-	elif [ "$sts" == "$T_FAIL_STATUS" ]; then
-		echo "  [ failed: $message ]"
-		echo "$test_name $message" >> "$T_RESULTS/fail.log"
-		((failed++))
-
-		test -n "$T_ABORT" && die "aborting after first failure"
-	fi
-
-	# record results for TAP format output
-	t_tap_progress $test_name $sts
-	((testcount++))
-
+	stop_tracing
 done
 
 msg "all tests run: $passed passed, $skipped skipped, $skipped_permitted skipped (permitted), $failed failed"
 
-
-if [ -n "$T_TRACE_GLOB" -o -n "$T_TRACE_PRINTK" ]; then
-	msg "saving traces and disabling tracing"
-	echo 0 > /sys/kernel/debug/tracing/events/scoutfs/enable
-	echo 0 > /sys/kernel/debug/tracing/options/trace_printk
-	cat /sys/kernel/debug/tracing/trace > "$T_RESULTS/traces"
-	if [ -n "$orig_trace_size" ]; then
-		echo $orig_trace_size > /sys/kernel/debug/tracing/buffer_size_kb
-	fi
-fi
-
 if [ "$skipped" == 0 -a "$failed" == 0 ]; then
 	msg "all tests passed"
 	unmount_all

tests/tests/srch-safe-merge-pos.sh

@@ -31,8 +31,8 @@ trap restore_compact_delay EXIT
 
 echo "== arm compaction triggers"
 for nr in $(t_fs_nrs); do
-	t_trigger_arm srch_compact_logs_pad_safe $nr
-	t_trigger_arm srch_merge_stop_safe $nr
+	t_trigger_arm_silent srch_compact_logs_pad_safe $nr
+	t_trigger_arm_silent srch_merge_stop_safe $nr
 done
 
 echo "== compact more often"
@@ -44,7 +44,7 @@ echo "== create padded sorted inputs by forcing log rotation"
 sv=$(t_server_nr)
 for i in $(seq 1 $COMPACT_NR); do
 	for j in $(seq 1 $COMPACT_NR); do
-		t_trigger_arm srch_force_log_rotate $sv
+		t_trigger_arm_silent srch_force_log_rotate $sv
 
 		seq -f "f-$i-$j-$SEQF" 1 10 | \
 			bulk_create_paths -X "scoutfs.srch.t-srch-safe-merge-pos" -d "$T_D0" > \
@@ -59,7 +59,7 @@ for i in $(seq 1 $COMPACT_NR); do
 	while test $padded == 0 && sleep .5; do
 		for nr in $(t_fs_nrs); do
 			if [ "$(t_trigger_get srch_compact_logs_pad_safe $nr)" == "0" ]; then
-				t_trigger_arm srch_compact_logs_pad_safe $nr
+				t_trigger_arm_silent srch_compact_logs_pad_safe $nr
 				padded=1
 				break
 			fi