Torture-test updates for 4.5

PATCH Superseded Paul E. McKenney 2 participants 17 messages Dec 5, 2015 – Dec 6, 2015

Subsystems (4)

Kselftest RCU Torture-test modules Rcutorture test framework

lore

Share & tools

lore

Paul E. McKenney

author

2015-12-05 00:22 UTC #0 lore raw

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. Dump stack when RCU's grace-period kthread stalls.

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

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

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

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

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

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

Thanx, Paul

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

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

Paul E. McKenney

author

2015-12-05 00:23 UTC #1 lore raw

PATCH 1/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

---
 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

Paul E. McKenney

author

2015-12-05 00:23 UTC #2 lore raw

PATCH 2/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

---
 kernel/rcu/tree.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

kernel/rcu/tree.c +5 -2

index 81aa1cdc6bc9..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);
+		       rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
+		if (rsp->gp_kthread)
+			sched_show_task(rsp->gp_kthread);
+	}
 }
 
 /*

Signature · 1 line

2.5.2

Josh Triplett

maintainer

2015-12-05 00:59 UTC #3 lore raw

Re: [PATCH tip/core/rcu 2/8] rcutorture: Dump stack when GP kthread stalls

Quoted 2 lines · 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.

That's not everything this patch does; see below.

Quoted 11 lines

Signed-off-by Paul E. McKenney <[email protected]>

---
 kernel/rcu/tree.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

kernel/rcu/tree.c +0 -0

index 81aa1cdc6bc9..7b78c88e19a3 100644
@@ -1196,12 +1196,15 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)

kernel/rcu/tree.c static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp) · line 1204

Quoted 10 lines

kernel/rcu/tree.c +2 -2

 	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);
+		       rsp->gp_kthread ? rsp->gp_kthread->state : ~0);

The commit message doesn't explain this change. Could you please 1) document this change in the commit message, and 2) split it into a separate patch unless it directly relates to the other change (which doesn't seem like the case)?

Quoted 9 lines

kernel/rcu/tree.c +3 -0

+		if (rsp->gp_kthread)
+			sched_show_task(rsp->gp_kthread);
+	}
 }
 
 /*

Signature · 1 line

2.5.2

Paul E. McKenney

author

2015-12-06 01:44 UTC #4 lore raw

Re: [PATCH tip/core/rcu 2/8] rcutorture: Dump stack when GP kthread stalls

Quoted 17 lines · Josh Triplett

Quoted 2 lines · 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.
That's not everything this patch does; see below.
Quoted 11 lines
Signed-off-by Paul E. McKenney <[email protected]>
---
 kernel/rcu/tree.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)
kernel/rcu/tree.c +0 -0
index 81aa1cdc6bc9..7b78c88e19a3 100644
@@ -1196,12 +1196,15 @@ static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp)
 

Quoted 15 lines

kernel/rcu/tree.c static void rcu_check_gp_kthread_starvation(struct rcu_state *rsp) · line 1204
Quoted 10 lines
kernel/rcu/tree.c +2 -2
 	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);
+		       rsp->gp_kthread ? rsp->gp_kthread->state : ~0);
The commit message doesn't explain this change. Could you please 1) document this change in the commit message, and 2) split it into a separate patch unless it directly relates to the other change (which doesn't seem like the case)?

Good point, especially given that it took me some time to remember why that change was necessary. It is now in a separate commit, with a commit log stating that this disambiguates the case where there is no RCU GP kthread from the case where there is a TASK_RUNNING RCU GP kthread.

Thanx, Paul

Quoted 10 lines

Quoted 9 lines
kernel/rcu/tree.c +3 -0
+		if (rsp->gp_kthread)
+			sched_show_task(rsp->gp_kthread);
+	}
 }
 
 /*
Signature · 1 line
2.5.2

Paul E. McKenney

author

2015-12-05 00:23 UTC #5 lore raw

PATCH 3/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

---
 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

Paul E. McKenney

author

2015-12-05 00:23 UTC #6 lore raw

PATCH 4/8 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.

Signed-off-by Yang Shi <[email protected]>

Signed-off-by Paul E. McKenney <[email protected]>

Acked-by Frederic Weisbecker <[email protected]>

---
 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

Paul E. McKenney

author

2015-12-05 00:23 UTC #7 lore raw

PATCH 5/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

---
 kernel/rcu/rcutorture.c | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)

kernel/rcu/rcutorture.c +23 -1

index d89328e260df..adbb194e2b5d 100644
@@ -162,6 +162,27 @@ static int rcu_torture_writer_state;
 #define RTWS_SYNC		7
 #define RTWS_STUTTER		8
 #define RTWS_STOPPING		9
+static 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",
+};
+
+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

Josh Triplett

maintainer

2015-12-05 01:02 UTC #8 lore raw

Re: [PATCH tip/core/rcu 5/8] rcutorture: Print symbolic name for rcu_torture_writer_state

Quoted 14 lines · 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.
Signed-off-by Paul E. McKenney <[email protected]>
---
 kernel/rcu/rcutorture.c | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)
kernel/rcu/rcutorture.c +0 -0
index d89328e260df..adbb194e2b5d 100644

kernel/rcu/rcutorture.c static int rcu_torture_writer_state; · line 165

Quoted 4 lines

kernel/rcu/rcutorture.c +1 -0

@@ -162,6 +162,27 @@ static int rcu_torture_writer_state;
 #define RTWS_SYNC		7
 #define RTWS_STUTTER		8
 #define RTWS_STOPPING		9
+static char * const rcu_torture_writer_state_names[] = {

Shouldn't this use "static const char * const"? Also, see below.

kernel/rcu/rcutorture.c static int rcu_torture_writer_state; · line 178

Quoted 13 lines

kernel/rcu/rcutorture.c +13 -0

+	"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",
+};
+
+char *rcu_torture_writer_state_getname(void)

This should return "const char *", I think.

Quoted 23 lines

kernel/rcu/rcutorture.c +9 -1

+{
+	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

Paul E. McKenney

author

2015-12-06 01:45 UTC #9 lore raw

Re: [PATCH tip/core/rcu 5/8] rcutorture: Print symbolic name for rcu_torture_writer_state

Quoted 10 lines · Josh Triplett

Quoted 9 lines · 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.
Signed-off-by Paul E. McKenney <[email protected]>
---
 kernel/rcu/rcutorture.c | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)

Quoted 11 lines

kernel/rcu/rcutorture.c static int rcu_torture_writer_state; · line 165
Quoted 9 lines
kernel/rcu/rcutorture.c +1 -0
index d89328e260df..adbb194e2b5d 100644
@@ -162,6 +162,27 @@ static int rcu_torture_writer_state;
 #define RTWS_SYNC		7
 #define RTWS_STUTTER		8
 #define RTWS_STOPPING		9
+static char * const rcu_torture_writer_state_names[] = {
Shouldn't this use "static const char * const"? Also, see below.

Can't hurt...

Quoted 7 lines

kernel/rcu/rcutorture.c +7 -0

+	"RTWS_FIXED_DELAY",
+	"RTWS_DELAY",
+	"RTWS_REPLACE",
+	"RTWS_DEF_FREE",
+	"RTWS_EXP_SYNC",
+	"RTWS_COND_GET",
+	"RTWS_COND_SYNC",

Quoted 8 lines

kernel/rcu/rcutorture.c static int rcu_torture_writer_state; · line 178
Quoted 6 lines
kernel/rcu/rcutorture.c +6 -0
+	"RTWS_SYNC",
+	"RTWS_STUTTER",
+	"RTWS_STOPPING",
+};
+
+char *rcu_torture_writer_state_getname(void)
This should return "const char *", I think.

Yes, especially once I had made the earlier change. Also made this function be static while I was at it.

Thanx, Paul

Quoted 24 lines

Quoted 23 lines

kernel/rcu/rcutorture.c +9 -1

+{
+	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

Paul E. McKenney

author

2015-12-05 00:24 UTC #10 lore raw

PATCH 6/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

[ Updated to fix relational operator called out by Dan Carpenter. ]

---
 kernel/rcu/tree.c | 15 +++++++++++++--
 kernel/rcu/tree.h |  9 +++++++++
 2 files changed, 22 insertions(+), 2 deletions(-)

kernel/rcu/tree.c +13 -2

index 7b78c88e19a3..491c99a73996 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 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 +9 -0

index f32bebb6bc90..f0304988e3f8 100644
@@ -544,6 +544,15 @@ struct rcu_state {
 #define RCU_GP_DOING_FQS 4	/* Wait done for force-quiescent-state time. */
 #define RCU_GP_CLEANUP   5	/* Grace-period cleanup started. */
 #define RCU_GP_CLEANED   6	/* Grace-period cleanup complete. */
+static 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",
+};
 
 extern struct list_head rcu_struct_flavors;

Signature · 1 line

2.5.2

Josh Triplett

maintainer

2015-12-05 01:04 UTC #11 lore raw

Re: [PATCH tip/core/rcu 6/8] rcutorture: Print symbolic name for ->gp_state

Quoted 15 lines · 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.
Signed-off-by Paul E. McKenney <[email protected]>
[ Updated to fix relational operator called out by Dan Carpenter. ]
---
 kernel/rcu/tree.c | 15 +++++++++++++--
 kernel/rcu/tree.h |  9 +++++++++
 2 files changed, 22 insertions(+), 2 deletions(-)
kernel/rcu/tree.c +0 -0
index 7b78c88e19a3..491c99a73996 100644

kernel/rcu/tree.c static void record_gp_stall_check_time(struct rcu_state *rsp) · line 1192

Quoted 6 lines

kernel/rcu/tree.c +3 -0

@@ -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 char *gp_state_getname(short gs)

Same comment about "const char *"

Quoted 29 lines

kernel/rcu/tree.c +10 -2

+{
+	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 +0 -0

index f32bebb6bc90..f0304988e3f8 100644

kernel/rcu/tree.h struct rcu_state { · line 547

Quoted 4 lines

kernel/rcu/tree.h +1 -0

@@ -544,6 +544,15 @@ struct rcu_state {
 #define RCU_GP_DOING_FQS 4	/* Wait done for force-quiescent-state time. */
 #define RCU_GP_CLEANUP   5	/* Grace-period cleanup started. */
 #define RCU_GP_CLEANED   6	/* Grace-period cleanup complete. */
+static char * const gp_state_names[] = {

Same comment about "const char * const", but also, should this really go in a header file? Do any circumstances exist where this header could get included in more than one source file in a given build? If so, multiple copies of this array could potentially end up in the binary, if the compiler fails to merge them.

Quoted 14 lines

kernel/rcu/tree.h +8 -0

+	"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",
+};
 
 extern struct list_head rcu_struct_flavors;

Signature · 1 line

2.5.2

Paul E. McKenney

author

2015-12-06 01:53 UTC #12 lore raw

Re: [PATCH tip/core/rcu 6/8] rcutorture: Print symbolic name for ->gp_state

Quoted 18 lines · Josh Triplett

Quoted 17 lines · 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.
Signed-off-by Paul E. McKenney <[email protected]>
[ Updated to fix relational operator called out by Dan Carpenter. ]
---
 kernel/rcu/tree.c | 15 +++++++++++++--
 kernel/rcu/tree.h |  9 +++++++++
 2 files changed, 22 insertions(+), 2 deletions(-)
kernel/rcu/tree.c +0 -0
index 7b78c88e19a3..491c99a73996 100644
@@ -1187,6 +1187,16 @@ static void record_gp_stall_check_time(struct rcu_state *rsp)
 }
 

Quoted 6 lines

kernel/rcu/tree.c static void record_gp_stall_check_time(struct rcu_state *rsp) · line 1192
Quoted 4 lines
kernel/rcu/tree.c +3 -0
 /*
+ * Convert a ->gp_state value to a character string.
+ */
+static char *gp_state_getname(short gs)
Same comment about "const char *"

Good point, fixed!

Quoted 31 lines

kernel/rcu/tree.c +10 -2

+{
+	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 +0 -0

index f32bebb6bc90..f0304988e3f8 100644
@@ -544,6 +544,15 @@ struct rcu_state {
 #define RCU_GP_DOING_FQS 4	/* Wait done for force-quiescent-state time. */
 #define RCU_GP_CLEANUP   5	/* Grace-period cleanup started. */

Quoted 8 lines

kernel/rcu/tree.h struct rcu_state { · line 547
Quoted 2 lines
kernel/rcu/tree.h +1 -0
 #define RCU_GP_CLEANED   6	/* Grace-period cleanup complete. */
+static char * const gp_state_names[] = {
Same comment about "const char * const", but also, should this really go in a header file? Do any circumstances exist where this header could get included in more than one source file in a given build? If so, multiple copies of this array could potentially end up in the binary, if the compiler fails to merge them.

I added the const.

However, I left the array in the .h file. The issue is that the #defines really have to be in the tree.h file. Given that, if I move the array elsewhere, they will very likely drift out of sync. So this sounds like a job for the compiler/linker...

Ah, but there is another approach. It turns out that tree.h in included only from tree.c and tree_trace.c. And tree_trace.c defines a CPP symbol RCU_TREE_NONCORE that is used elsewhere in tree.h to keep tree_trace.c's mitts off a number of attractive but dangerous functions. So I just put the array under "#ifndef RCU_TREE_NONCORE".

Fair enough?

Thanx, Paul

Quoted 15 lines

Quoted 14 lines

kernel/rcu/tree.h +8 -0

+	"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",
+};
 
 extern struct list_head rcu_struct_flavors;

Signature · 1 line

2.5.2

Josh Triplett

maintainer Reviewed-by

2015-12-06 01:57 UTC #13 lore raw

Re: [PATCH tip/core/rcu 6/8] rcutorture: Print symbolic name for ->gp_state

Quoted 75 lines · Paul E. McKenney

Quoted 18 lines · Josh Triplett
Quoted 17 lines · 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.
Signed-off-by Paul E. McKenney <[email protected]>
[ Updated to fix relational operator called out by Dan Carpenter. ]
---
 kernel/rcu/tree.c | 15 +++++++++++++--
 kernel/rcu/tree.h |  9 +++++++++
 2 files changed, 22 insertions(+), 2 deletions(-)
kernel/rcu/tree.c +0 -0
index 7b78c88e19a3..491c99a73996 100644
@@ -1187,6 +1187,16 @@ static void record_gp_stall_check_time(struct rcu_state *rsp)
 }
 
Quoted 6 lines
kernel/rcu/tree.c static void record_gp_stall_check_time(struct rcu_state *rsp) · line 1192
Quoted 4 lines
kernel/rcu/tree.c +3 -0
 /*
+ * Convert a ->gp_state value to a character string.
+ */
+static char *gp_state_getname(short gs)
Same comment about "const char *"
Good point, fixed!
Quoted 31 lines
Quoted 31 lines
kernel/rcu/tree.c +10 -2
+{
+	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 +0 -0
index f32bebb6bc90..f0304988e3f8 100644
@@ -544,6 +544,15 @@ struct rcu_state {
 #define RCU_GP_DOING_FQS 4	/* Wait done for force-quiescent-state time. */
 #define RCU_GP_CLEANUP   5	/* Grace-period cleanup started. */
Quoted 8 lines
kernel/rcu/tree.h struct rcu_state { · line 547
Quoted 2 lines
kernel/rcu/tree.h +1 -0
 #define RCU_GP_CLEANED   6	/* Grace-period cleanup complete. */
+static char * const gp_state_names[] = {
Same comment about "const char * const", but also, should this really go in a header file? Do any circumstances exist where this header could get included in more than one source file in a given build? If so, multiple copies of this array could potentially end up in the binary, if the compiler fails to merge them.
I added the const.
However, I left the array in the .h file. The issue is that the #defines really have to be in the tree.h file. Given that, if I move the array elsewhere, they will very likely drift out of sync. So this sounds like a job for the compiler/linker...

Quoted 7 lines

Ah, but there is another approach. It turns out that tree.h in included only from tree.c and tree_trace.c. And tree_trace.c defines a CPP symbol RCU_TREE_NONCORE that is used elsewhere in tree.h to keep tree_trace.c's mitts off a number of attractive but dangerous functions. So I just put the array under "#ifndef RCU_TREE_NONCORE".
Fair enough?

Fair enough.

Reviewed-by Josh Triplett <[email protected]>

Paul E. McKenney

author

2015-12-05 00:24 UTC #14 lore raw

PATCH 7/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

---
 .../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

Paul E. McKenney

author

2015-12-05 00:23 UTC #15 lore raw

PATCH 8/8 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.

Signed-off-by Paul E. McKenney <[email protected]>

---
 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

Josh Triplett

maintainer Reviewed-by on the v1 series

2015-12-05 01:05 UTC #16 lore raw

In reply to Paul E. McKenney

Quoted 19 lines · Paul E. McKenney

Hello!
This series contains torture-test updates:
1. Add batch number to script printout to allow easier estimation
of test duration.
2. Dump stack when RCU's grace-period kthread stalls.
3. Set the scripting's default test-hang "grace period" to three
minutes, and allow this to be overridden.
4. Remove the obsolete CONFIG_RCU_USER_QS Kconfig option from
the rcutorture selftest documentation, courtesy of Yang Shi.
5. Print symbolic name for rcu_torture_writer_state, saving the
time otherwise required to manually translate from integer to symbol.

Quoted 8 lines

6. Print symbolic name for ->gp_state, again saving the time
otherwise required to manually translate from integer to symbol.
7. Abbreviate console error dump, allowing the results of an
rcutorture script run to be observed with less back-scrolling.
8. Place console.log files correctly from the get-go, preventing
multiple qemu instances from outputting to the same file.

I sent comments on patches 2, 5, and 6; for the rest:

Reviewed-by Josh Triplett <[email protected]>