Skip to contentSkip to conversation

Torture-test updates for 4.5

PATCH New Paul E. McKenney 1 participant 10 messages Dec 9, 2015

Subsystems (4)
lore
Share & tools
lore
#0 lore raw

v2 cover Torture-test updates for 4.5

Hello!

This series contains torture-test updates:

1. Add batch number to script printout to allow easier estimation
of test duration.

2. Flag non-existent RCU grace-period kthread.

3. Dump stack when RCU's grace-period kthread stalls.

4. Set the scripting's default test-hang "grace period" to three
minutes, and allow this to be overridden.

5. Remove the obsolete CONFIG_RCU_USER_QS Kconfig option from
the rcutorture selftest documentation, courtesy of Yang Shi.

6. Print symbolic name for rcu_torture_writer_state, saving the
time otherwise required to manually translate from integer to symbol.

7. Print symbolic name for ->gp_state, again saving the time
otherwise required to manually translate from integer to symbol.

8. Abbreviate console error dump, allowing the results of an
rcutorture script run to be observed with less back-scrolling.

9. Place console.log files correctly from the get-go, preventing
multiple qemu instances from outputting to the same file.

Changes since v1:

o Apply Josh Triplett review feedback.

o Split v1's patch #2 into two patches (#2 and #3 above).

Thanx, Paul

------------------------------------------------------------------------

 kernel/rcu/rcutorture.c                                     |   24 ++++++-
 kernel/rcu/tree.c                                           |   22 +++++-
 kernel/rcu/tree.h                                           |   12 +++
 tools/testing/selftests/rcutorture/bin/kvm-test-1-run.sh    |    9 --
 tools/testing/selftests/rcutorture/bin/kvm.sh               |   22 ++++--
 tools/testing/selftests/rcutorture/bin/parse-console.sh     |   41 ++++++++++--
 tools/testing/selftests/rcutorture/doc/TINY_RCU.txt         |    1 
 tools/testing/selftests/rcutorture/doc/TREE_RCU-kconfig.txt |    4 -
 8 files changed, 107 insertions(+), 28 deletions(-)
#1 lore raw

PATCH v2 1/9 rcutorture: Add batch number to script printout

Currently, the scripts print "----Start batch" at the beginning of each batch, which does serve as a good visual delimiter between batches. Unfortunately, if there are a lot of batches, it is hard to quickly estimate test runtime from the output of "--dryrun sched". This commit therefore adds a batch number, so that the beginning-of-batch output looks like this "----Start batch 10" for the tenth batch.

---
 tools/testing/selftests/rcutorture/bin/kvm.sh | 15 +++++++++------
 1 file changed, 9 insertions(+), 6 deletions(-)
tools/testing/selftests/rcutorture/bin/kvm.sh +9 -6
index f6483609ebc2..013c48239a66 100755
@@ -307,10 +307,10 @@ awk < $T/cfgcpu.pack \
 }
 
 # Dump out the scripting required to run one test batch.
-function dump(first, pastlast)
+function dump(first, pastlast, batchnum)
 {
-	print "echo ----Start batch: `date`";
-	print "echo ----Start batch: `date` >> " rd "/log";
+	print "echo ----Start batch " batchnum ": `date`";
+	print "echo ----Start batch " batchnum ": `date` >> " rd "/log";
 	jn=1
 	for (j = first; j < pastlast; j++) {
 		builddir=KVM "/b" jn
@@ -371,25 +371,28 @@ END {
 	njobs = i;
 	nc = ncpus;
 	first = 0;
+	batchnum = 1;
 
 	# Each pass through the following loop considers one test.
 	for (i = 0; i < njobs; i++) {
 		if (ncpus == 0) {
 			# Sequential test specified, each test its own batch.
-			dump(i, i + 1);
+			dump(i, i + 1, batchnum);
 			first = i;
+			batchnum++;
 		} else if (nc < cpus[i] && i != 0) {
 			# Out of CPUs, dump out a batch.
-			dump(first, i);
+			dump(first, i, batchnum);
 			first = i;
 			nc = ncpus;
+			batchnum++;
 		}
 		# Account for the CPUs needed by the current test.
 		nc -= cpus[i];
 	}
 	# Dump the last batch.
 	if (ncpus != 0)
-		dump(first, i);
+		dump(first, i, batchnum);
 }' >> $T/script
 
 cat << ___EOF___ >> $T/script
Signature · 1 line
2.5.2
#2 lore raw

PATCH v2 2/9 rcutorture: Flag nonexistent RCU GP kthread

In reply to Paul E. McKenney

Currently, if the RCU grace-period kthread has not yet been created, in which case the starvation-check code will print zero for the state, which maps to TASK_RUNNING. This could clearly be quite confusing, so this commit prints ~0, which does not map to any legal ->state value.

---
 kernel/rcu/tree.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/rcu/tree.c +1 -1
index 81aa1cdc6bc9..e2315fb57b23 100644
@@ -1201,7 +1201,7 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
 		       rsp->name, j - gpa,
 		       rsp->gpnum, rsp->completed,
 		       rsp->gp_flags, rsp->gp_state,
-		       rsp->gp_kthread ? rsp->gp_kthread->state : 0);
+		       rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
 }
 
 /*
Signature · 1 line
2.5.2
#3 lore raw

PATCH v2 3/9 rcutorture: Dump stack when GP kthread stalls

In reply to Paul E. McKenney

This commit increases debug information in the case where the grace-period kthread is being prevented from running by dumping that kthread's stack.

[ paulmck: Split into prior commit and this commit, as suggested by
Josh Triplett. ]

---
 kernel/rcu/tree.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)
kernel/rcu/tree.c +4 -1
index e2315fb57b23..7b78c88e19a3 100644
@@ -1196,12 +1196,15 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
 
 	j = jiffies;
 	gpa = READ_ONCE(rsp->gp_activity);
-	if (j - gpa > 2 * HZ)
+	if (j - gpa > 2 * HZ) {
 		pr_err("%s kthread starved for %ld jiffies! g%lu c%lu f%#x s%d ->state=%#lx\n",
 		       rsp->name, j - gpa,
 		       rsp->gpnum, rsp->completed,
 		       rsp->gp_flags, rsp->gp_state,
 		       rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
+		if (rsp->gp_kthread)
+			sched_show_task(rsp->gp_kthread);
+	}
 }
 
 /*
Signature · 1 line
2.5.2
#4 lore raw

PATCH v2 4/9 rcutorture: Default grace period to three minutes, allow override

In reply to Paul E. McKenney

The default test grace period of two minutes is insufficient in some cases and excessive in others. This commit therefore increases the default to three minutes, but also adds a --shutdown-grace parameter to allow the default to be overridden.

---
 tools/testing/selftests/rcutorture/bin/kvm-test-1-run.sh | 4 +---
 tools/testing/selftests/rcutorture/bin/kvm.sh            | 7 +++++++
 2 files changed, 8 insertions(+), 3 deletions(-)
tools/testing/selftests/rcutorture/bin/kvm-test-1-run.sh +1 -3
index 5236e073919d..d39273dae464 100755
@@ -38,8 +38,6 @@
 #
 # Authors: Paul E. McKenney <[email protected]>
 
-grace=120
-
 T=/tmp/kvm-test-1-run.sh.$$
 trap 'rm -rf $T' 0
 touch $T
@@ -214,7 +212,7 @@ then
 		else
 			break
 		fi
-		if test $kruntime -ge $((seconds + grace))
+		if test $kruntime -ge $((seconds + $TORTURE_SHUTDOWN_GRACE))
 		then
 			echo "!!! PID $qemu_pid hung at $kruntime vs. $seconds seconds" >> $resdir/Warnings 2>&1
 			kill -KILL $qemu_pid
tools/testing/selftests/rcutorture/bin/kvm.sh +7 -0
index 013c48239a66..4a431767f77a 100755
@@ -42,6 +42,7 @@ TORTURE_DEFCONFIG=defconfig
 TORTURE_BOOT_IMAGE=""
 TORTURE_INITRD="$KVM/initrd"; export TORTURE_INITRD
 TORTURE_KMAKE_ARG=""
+TORTURE_SHUTDOWN_GRACE=180
 TORTURE_SUITE=rcu
 resdir=""
 configs=""
@@ -149,6 +150,11 @@ do
 		resdir=$2
 		shift
 		;;
+	--shutdown-grace)
+		checkarg --shutdown-grace "(seconds)" "$#" "$2" '^[0-9]*$' '^error'
+		TORTURE_SHUTDOWN_GRACE=$2
+		shift
+		;;
 	--torture)
 		checkarg --torture "(suite name)" "$#" "$2" '^\(lock\|rcu\)$' '^--'
 		TORTURE_SUITE=$2
@@ -266,6 +272,7 @@ TORTURE_KMAKE_ARG="$TORTURE_KMAKE_ARG"; export TORTURE_KMAKE_ARG
 TORTURE_QEMU_CMD="$TORTURE_QEMU_CMD"; export TORTURE_QEMU_CMD
 TORTURE_QEMU_INTERACTIVE="$TORTURE_QEMU_INTERACTIVE"; export TORTURE_QEMU_INTERACTIVE
 TORTURE_QEMU_MAC="$TORTURE_QEMU_MAC"; export TORTURE_QEMU_MAC
+TORTURE_SHUTDOWN_GRACE="$TORTURE_SHUTDOWN_GRACE"; export TORTURE_SHUTDOWN_GRACE
 TORTURE_SUITE="$TORTURE_SUITE"; export TORTURE_SUITE
 if ! test -e $resdir
 then
Signature · 1 line
2.5.2
#5 lore raw

PATCH v2 5/9 rcutorture: Remove CONFIG_RCU_USER_QS from rcutorture selftest doc

In reply to Paul E. McKenney

From: Yang Shi <[email protected]>

Commit d1ec4c34c7a9 ("rcu: Drop RCU_USER_QS in favor of NO_HZ_FULL") has removed RCU_USER_QS from Kconfig file, so remove it from some documents to avoid any confusion.

---
 tools/testing/selftests/rcutorture/doc/TINY_RCU.txt         | 1 -
 tools/testing/selftests/rcutorture/doc/TREE_RCU-kconfig.txt | 4 ----
 2 files changed, 5 deletions(-)
tools/testing/selftests/rcutorture/doc/TINY_RCU.txt +0 -1
index 9ef33a743b73..24396ae8355b 100644
@@ -20,7 +20,6 @@ CONFIG_PROVE_RCU
 
 CONFIG_NO_HZ_FULL_SYSIDLE
 CONFIG_RCU_NOCB_CPU
-CONFIG_RCU_USER_QS
 
 	Meaningless for TINY_RCU.
 
tools/testing/selftests/rcutorture/doc/TREE_RCU-kconfig.txt +0 -4
index 657f3a035488..4e2b1893d40d 100644
@@ -72,10 +72,6 @@ CONFIG_RCU_TORTURE_TEST_RUNNABLE
 
 	Always used in KVM testing.
 
-CONFIG_RCU_USER_QS
-
-	Redundant with CONFIG_NO_HZ_FULL.
-
 CONFIG_PREEMPT_RCU
 CONFIG_TREE_RCU
 
Signature · 1 line
2.5.2
#6 lore raw

PATCH v2 6/9 rcutorture: Print symbolic name for rcu_torture_writer_state

In reply to Paul E. McKenney

Currently, rcu_torture_writer_state is printed as an integer, which slows debugging. This commit therefore prints a symbolic name in addition to the integer.

[ paulmck: More "const", as suggested by Josh Triplett. ]
---
 kernel/rcu/rcutorture.c | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)
kernel/rcu/rcutorture.c +23 -1
index d89328e260df..d2988d047d66 100644
@@ -162,6 +162,27 @@ static int rcu_torture_writer_state;
 #define RTWS_SYNC		7
 #define RTWS_STUTTER		8
 #define RTWS_STOPPING		9
+static const char * const rcu_torture_writer_state_names[] = {
+	"RTWS_FIXED_DELAY",
+	"RTWS_DELAY",
+	"RTWS_REPLACE",
+	"RTWS_DEF_FREE",
+	"RTWS_EXP_SYNC",
+	"RTWS_COND_GET",
+	"RTWS_COND_SYNC",
+	"RTWS_SYNC",
+	"RTWS_STUTTER",
+	"RTWS_STOPPING",
+};
+
+static const char *rcu_torture_writer_state_getname(void)
+{
+	unsigned int i = READ_ONCE(rcu_torture_writer_state);
+
+	if (i >= ARRAY_SIZE(rcu_torture_writer_state_names))
+		return "???";
+	return rcu_torture_writer_state_names[i];
+}
 
 #if defined(MODULE) || defined(CONFIG_RCU_TORTURE_TEST_RUNNABLE)
 #define RCUTORTURE_RUNNABLE_INIT 1
@@ -1307,7 +1328,8 @@ rcu_torture_stats_print(void)
 
 		rcutorture_get_gp_data(cur_ops->ttype,
 				       &flags, &gpnum, &completed);
-		pr_alert("??? Writer stall state %d g%lu c%lu f%#x\n",
+		pr_alert("??? Writer stall state %s(%d) g%lu c%lu f%#x\n",
+			 rcu_torture_writer_state_getname(),
 			 rcu_torture_writer_state,
 			 gpnum, completed, flags);
 		show_rcu_gp_kthreads();
Signature · 1 line
2.5.2
#7 lore raw

PATCH v2 7/9 rcutorture: Print symbolic name for ->gp_state

In reply to Paul E. McKenney

Currently, ->gp_state is printed as an integer, which slows debugging. This commit therefore prints a symbolic name in addition to the integer.

[ paulmck: Updated to fix relational operator called out by Dan Carpenter. ]
[ paulmck: More "const", as suggested by Josh Triplett. ]
---
 kernel/rcu/tree.c | 15 +++++++++++++--
 kernel/rcu/tree.h | 12 ++++++++++++
 2 files changed, 25 insertions(+), 2 deletions(-)
kernel/rcu/tree.c +13 -2
index 7b78c88e19a3..316354109734 100644
@@ -1187,6 +1187,16 @@ static void record_gp_stall_check_time(struct rcu_state *rsp)
 }
 
 /*
+ * Convert a ->gp_state value to a character string.
+ */
+static const char *gp_state_getname(short gs)
+{
+	if (gs < 0 || gs >= ARRAY_SIZE(gp_state_names))
+		return "???";
+	return gp_state_names[gs];
+}
+
+/*
  * Complain about starvation of grace-period kthread.
  */
 static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
@@ -1197,10 +1207,11 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
 	j = jiffies;
 	gpa = READ_ONCE(rsp->gp_activity);
 	if (j - gpa > 2 * HZ) {
-		pr_err("%s kthread starved for %ld jiffies! g%lu c%lu f%#x s%d ->state=%#lx\n",
+		pr_err("%s kthread starved for %ld jiffies! g%lu c%lu f%#x %s(%d) ->state=%#lx\n",
 		       rsp->name, j - gpa,
 		       rsp->gpnum, rsp->completed,
-		       rsp->gp_flags, rsp->gp_state,
+		       rsp->gp_flags,
+		       gp_state_getname(rsp->gp_state), rsp->gp_state,
 		       rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
 		if (rsp->gp_kthread)
 			sched_show_task(rsp->gp_kthread);
kernel/rcu/tree.h +12 -0
index f32bebb6bc90..a3fb6fe94127 100644
@@ -545,6 +545,18 @@ struct rcu_state {
 #define RCU_GP_CLEANUP   5	/* Grace-period cleanup started. */
 #define RCU_GP_CLEANED   6	/* Grace-period cleanup complete. */
 
+#ifndef RCU_TREE_NONCORE
+static const char * const gp_state_names[] = {
+	"RCU_GP_IDLE",
+	"RCU_GP_WAIT_GPS",
+	"RCU_GP_DONE_GPS",
+	"RCU_GP_WAIT_FQS",
+	"RCU_GP_DOING_FQS",
+	"RCU_GP_CLEANUP",
+	"RCU_GP_CLEANED",
+};
+#endif /* #ifndef RCU_TREE_NONCORE */
+
 extern struct list_head rcu_struct_flavors;
 
 /* Sequence through rcu_state structures for each RCU flavor. */
Signature · 1 line
2.5.2
#8 lore raw

PATCH v2 8/9 torture: Abbreviate console error dump

In reply to Paul E. McKenney

Currently, the scripts print a list of warning/bug indicators from the console.log file. This works well if there are only a few warnings or bugs, but can be quite annoying if there is a large number. This commit therefore prints a summary listing the number of each type of warning/bug indicator, but only if there is at least one such indicator. The full list is stored in the results directory at console.log.diags, which makes it easier to find the warning/bugs in the full console.log.

---
 .../selftests/rcutorture/bin/parse-console.sh      | 41 ++++++++++++++++++----
 1 file changed, 35 insertions(+), 6 deletions(-)
tools/testing/selftests/rcutorture/bin/parse-console.sh +35 -6
index d8f35cf116be..844787a0d7be 100755
@@ -24,9 +24,6 @@
 #
 # Authors: Paul E. McKenney <[email protected]>
 
-T=/tmp/abat-chk-badness.sh.$$
-trap 'rm -f $T' 0
-
 file="$1"
 title="$2"
 
@@ -36,9 +33,41 @@ if grep -Pq '\x00' < $file
 then
 	print_warning Console output contains nul bytes, old qemu still running?
 fi
-egrep 'Badness|WARNING:|Warn|BUG|===========|Call Trace:|Oops:|Stall ended before state dump start' < $file | grep -v 'ODEBUG: ' | grep -v 'Warning: unable to open an initial console' > $T
-if test -s $T
+egrep 'Badness|WARNING:|Warn|BUG|===========|Call Trace:|Oops:|detected stalls on CPUs/tasks:|Stall ended before state dump start' < $file | grep -v 'ODEBUG: ' | grep -v 'Warning: unable to open an initial console' > $1.diags
+if test -s $1.diags
 then
 	print_warning Assertion failure in $file $title
-	cat $T
+	# cat $1.diags
+	summary=""
+	n_badness=`grep -c Badness $1`
+	if test "$n_badness" -ne 0
+	then
+		summary="$summary  Badness: $n_badness"
+	fi
+	n_warn=`grep -v 'Warning: unable to open an initial console' $1 | egrep -c 'WARNING:|Warn'`
+	if test "$n_warn" -ne 0
+	then
+		summary="$summary  Warnings: $n_warn"
+	fi
+	n_bugs=`egrep -c 'BUG|Oops:' $1`
+	if test "$n_bugs" -ne 0
+	then
+		summary="$summary  Bugs: $n_bugs"
+	fi
+	n_calltrace=`grep -c 'Call Trace:' $1`
+	if test "$n_calltrace" -ne 0
+	then
+		summary="$summary  Call Traces: $n_calltrace"
+	fi
+	n_lockdep=`grep -c =========== $1`
+	if test "$n_badness" -ne 0
+	then
+		summary="$summary  lockdep: $n_badness"
+	fi
+	n_stalls=`egrep -c 'detected stalls on CPUs/tasks:|Stall ended before state dump start' $1`
+	if test "$n_stalls" -ne 0
+	then
+		summary="$summary  Stalls: $n_stalls"
+	fi
+	print_warning Summary: $summary
 fi
Signature · 1 line
2.5.2
#9 lore raw

PATCH v2 9/9 torture: Place console.log files correctly from the get-go

In reply to Paul E. McKenney

Currently, the console output files ("console.log") are placed in the build directory initially, then copied to the results directory. One problem with this is if a qemu refuses to die in a timely fashion after a kernel hang, it will continue to write after the next qemu starts up, resulting in confusing output from the old instance of qemu. This commit prevents such confusion by placing the console.log files into the results directory to begin with, so that a given instance of qemu is always writing only to its own console.log file.

---
 tools/testing/selftests/rcutorture/bin/kvm-test-1-run.sh | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)
tools/testing/selftests/rcutorture/bin/kvm-test-1-run.sh +2 -3
index d39273dae464..0f80eefb0bfd 100755
@@ -150,7 +150,7 @@ fi
 qemu_args="`specify_qemu_cpus "$QEMU" "$qemu_args" "$cpu_count"`"
 
 # Generate architecture-specific and interaction-specific qemu arguments
-qemu_args="$qemu_args `identify_qemu_args "$QEMU" "$builddir/console.log"`"
+qemu_args="$qemu_args `identify_qemu_args "$QEMU" "$resdir/console.log"`"
 
 # Generate qemu -append arguments
 qemu_append="`identify_qemu_append "$QEMU"`"
@@ -166,7 +166,7 @@ then
 	touch $resdir/buildonly
 	exit 0
 fi
-echo "NOTE: $QEMU either did not run or was interactive" > $builddir/console.log
+echo "NOTE: $QEMU either did not run or was interactive" > $resdir/console.log
 echo $QEMU $qemu_args -m 512 -kernel $resdir/bzImage -append \"$qemu_append $boot_args\" > $resdir/qemu-cmd
 ( $QEMU $qemu_args -m 512 -kernel $resdir/bzImage -append "$qemu_append $boot_args"; echo $? > $resdir/qemu-retval ) &
 qemu_pid=$!
@@ -222,6 +222,5 @@ then
 	done
 fi
 
-cp $builddir/console.log $resdir
 parse-torture.sh $resdir/console.log $title
 parse-console.sh $resdir/console.log $title
Signature · 1 line
2.5.2