scheduler hang on cpu re-hotplug with 2.6.27rc8

In reply to KOSAKI Motohiro

---

 include/linux/rcuclassic.h |    3 +
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    4 -
 kernel/rcuclassic_trace.c  |  126 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 133 insertions(+), 3 deletions(-)

include/linux/rcuclassic.h +3 -0

index 4ab8436..061a272 100644
@@ -54,6 +54,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {

kernel/Kconfig.preempt +0 -1

index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +2 -2

index aad93cd..517eaa9 100644
@@ -57,13 +57,13 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_bh_ctrlblk.lock),

kernel/rcuclassic_trace.c new file +126 -0

126 lines not on this page · raw message

Lai Jiangshan

2008-10-09 06:22 UTC #10 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 60 lines · Paul E. McKenney

Hello!
This is a tracing patch for Classic RCU, which creates an "rcu/rcucb" file in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.
Reading from the file results in something like the following:
	rcu: cur=1129  completed=1128  np=0  s=0
		0,3,7
	rcu_bh: cur=-287  completed=-287  np=0  s=0

	online: 0-7
The first two lines are for rcu, the second two for rcu_bh. The cur= is the current grace-period number, and the completed= is the number of the last completed grace period. If these two numbers are equal, the corresponding flavor of RCU is idle. The np= is a flag indicating that an additional RCU grace period beyond the current one will be required. The s=, if non-zero, indicates that a round of reschedule IPIs has been send to attempt to expedite the current grace period.
The second and fourth lines are a comma/dash-separated list of the CPUs that have not yet reported a quiescent state for the current grace period (CPUs 0, 3, and 7 for "rcu" above).
The last line lists the online CPUs.
Tested on x86 and Power.
Signed-off-by Paul E. McKenney <[email protected]>
---
 include/linux/rcuclassic.h |    3 +
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    4 -
 kernel/rcuclassic_trace.c  |  126 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 133 insertions(+), 3 deletions(-)
include/linux/rcuclassic.h +3 -0
index 4ab8436..061a272 100644
@@ -54,6 +54,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {
kernel/Kconfig.preempt +0 -0
index 9fdba03..ba32338 100644

kernel/Kconfig.preempt config PREEMPT_RCU · line 73

Quoted 7 lines

kernel/Kconfig.preempt +0 -1

@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

I think that we can move it to lib/Kconfig.debug.

Quoted 118 lines

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +2 -2

index aad93cd..517eaa9 100644
@@ -57,13 +57,13 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_bh_ctrlblk.lock),

kernel/rcuclassic_trace.c new file +79 -0

new file mode 100644
index 0000000..f8b9313
@@ -0,0 +1,126 @@
+/*
+ * Read-Copy Update tracing for classic implementation
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
+ *
+ * Copyright IBM Corporation, 2008
+ *
+ * Papers:  http://www.rdrop.com/users/paulmck/RCU
+ *
+ * For detailed explanation of Read-Copy Update mechanism see -
+ * 		Documentation/RCU
+ *
+ */
+#include <linux/types.h>
+#include <linux/kernel.h>
+#include <linux/init.h>
+#include <linux/spinlock.h>
+#include <linux/smp.h>
+#include <linux/rcupdate.h>
+#include <linux/interrupt.h>
+#include <linux/sched.h>
+#include <asm/atomic.h>
+#include <linux/bitops.h>
+#include <linux/module.h>
+#include <linux/completion.h>
+#include <linux/moduleparam.h>
+#include <linux/percpu.h>
+#include <linux/notifier.h>
+#include <linux/cpu.h>
+#include <linux/mutex.h>
+#include <linux/debugfs.h>
+
+static DEFINE_MUTEX(rcuclassic_trace_mutex);
+static char *rcuclassic_trace_buf;
+#define RCUCLASSIC_TRACE_BUF_SIZE (20*NR_CPUS + 100)
+
+static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+{
+	int cnt = 0;
+
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
+			"np=%d  s=%d\n\t",
+			rcp->cur, rcp->completed,
+			rcp->next_pending, rcp->signaled);
+	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
+	return cnt;
+}
+
+static ssize_t rcucb_read(struct file *filp, char __user *buffer,
+				size_t count, loff_t *ppos)
+{
+	ssize_t bcount;
+	char *buf = rcuclassic_trace_buf;
+	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
+
+	mutex_lock(&rcuclassic_trace_mutex);
+	buf += snprintf(buf, ebuf - buf, "rcu: ");
+	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
+	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "online: ");
+	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
+	buf += snprintf(buf, ebuf - buf, "\n");
+	bcount = simple_read_from_buffer(buffer, count, ppos,
+			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
+	mutex_unlock(&rcuclassic_trace_mutex);

kernel/rcuclassic_trace.c line 89

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+	return bcount;
+}
+
+static struct file_operations rcucb_fops = {
+	.owner = THIS_MODULE,
+	.read = rcucb_read,
+};
+
+static struct dentry *rcudir, *cbdir;
+static int rcuclassic_debugfs_init(void)

add __init:
static int __init rcuclassic_debugfs_init(void)

Quoted 9 lines

kernel/rcuclassic_trace.c new file +9 -0

+{
+	rcudir = debugfs_create_dir("rcu", NULL);
+	if (!rcudir)
+		goto out;
+	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
+	if (!cbdir)
+		goto free_out;
+	return 0;
+free_out:

kernel/rcuclassic_trace.c line 108

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+	debugfs_remove(rcudir);
+out:
+	return 1;
+}
+
+static int __init rcuclassic_trace_init(void)
+{
+	int ret;
+
+	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);

I'm wondering about this. rcuclassic_trace_buf is kmalloc-ed when init module.

In this case, why not define it as:
static char buf[20*NR_CPUS + 100];

and use it like:
pos += snprintf(buf + cnt, sizeof(buf) - cnt, ...);

Quoted 8 lines

kernel/rcuclassic_trace.c new file +8 -0

+	if (!rcuclassic_trace_buf)
+		return 1;
+	ret = rcuclassic_debugfs_init();
+	if (ret)
+		kfree(rcuclassic_trace_buf);
+	return ret;
+}
+

kernel/rcuclassic_trace.c line 126

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+static void __exit rcuclassic_trace_cleanup(void)
+{
+	debugfs_remove(cbdir);
+	debugfs_remove(rcudir);
+	kfree(rcuclassic_trace_buf);
+}
+
+
+module_init(rcuclassic_trace_init);
+module_exit(rcuclassic_trace_cleanup);

I think this trace file shows too little vars for classic rcu.

It is better that this trace file shows more data.
such as some data in struct rcu_data(quiescent state handling fields, batch, qlen).

or add new files: rcu/rcu_data<cpu#>

Thanks, Lai

Andi Kleen

author

2008-10-09 06:49 UTC #11 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 2 lines

In this case, why not define it as:
static char buf[20*NR_CPUS + 100];

Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.

And with num_possible_cpus() kmalloc is needed.

-Andi

Lai Jiangshan

2008-10-09 07:08 UTC #12 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 13 lines · Andi Kleen

Quoted 2 lines
In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.
And with num_possible_cpus() kmalloc is needed.
-Andi

I thought the default value of NR_CPUS is 32.

if NR_CPUS is too large, I think using seq_file is good idea, and rcuclassic_trace_mutex is not need too.

Lai

KOSAKI Motohiro

2008-10-09 07:14 UTC #13 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Hi Lai-san,

Quoted 10 lines

Quoted 8 lines
Quoted 2 lines
In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.
And with num_possible_cpus() kmalloc is needed.
I thought the default value of NR_CPUS is 32.

it's pointless.
Almost distribution use _very_ large NR_CPUS (likes 4096). So, We should concern large NR_CPUS.

Quoted 3 lines

if NR_CPUS is too large, I think using seq_file is good idea, and rcuclassic_trace_mutex is not need too.

Lai Jiangshan

2008-10-09 07:29 UTC #14 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 8 lines · KOSAKI Motohiro

Hi Lai-san,
Quoted 6 lines
Quoted 6 lines
Quoted 2 lines
In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.

Quoted 6 lines

Quoted 2 lines
Quoted 1 line
And with num_possible_cpus() kmalloc is needed.
I thought the default value of NR_CPUS is 32.
it's pointless.
Almost distribution use _very_ large NR_CPUS (likes 4096). So, We should concern large NR_CPUS.

Thanks.

So my advice is to use seq_file.

Quoted 9 lines

Quoted 4 lines
if NR_CPUS is too large, I think using seq_file is good idea, and rcuclassic_trace_mutex is not need too.

Andi Kleen

author

2008-10-09 07:59 UTC #15 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 9 lines · KOSAKI Motohiro

Hi Lai-san,
Quoted 7 lines
Quoted 7 lines
Quoted 2 lines
In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.

Quoted 6 lines

Quoted 3 lines
Quoted 1 line
And with num_possible_cpus() kmalloc is needed.
I thought the default value of NR_CPUS is 32.
it's pointless.
Almost distribution use _very_ large NR_CPUS (likes 4096).

Right now it's more like 8-128, but at least there is some effort to make a 4096 CPU distribution possible and Mike Travis has been
tirelessly working on eradicating all the rogue NR_CPUs all over
the tree. So it's better to not add more.

Quoted 1 line

So, We should concern large NR_CPUS.

Agreed.

-Andi

Signature · 1 line

[email protected]

Paul E. McKenney

2008-10-10 11:48 UTC #16 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

In reply to Lai Jiangshan

Quoted 8 lines · Lai Jiangshan

Quoted 7 lines · Andi Kleen
Quoted 2 lines
In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.

Quoted 8 lines

Quoted 3 lines
And with num_possible_cpus() kmalloc is needed.
-Andi
I thought the default value of NR_CPUS is 32.
if NR_CPUS is too large, I think using seq_file is good idea, and rcuclassic_trace_mutex is not need too.

I never have used seq_file, to be honest. I would welcome a patch from you applying it to my rcucb and rcudata patch set.

Thanx, Paul

Paul E. McKenney

2008-10-09 11:50 UTC #17 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

In reply to Andi Kleen

Quoted 8 lines · Andi Kleen

Quoted 2 lines
In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
Actually you should near never use NR_CPUS now but always num_possible_cpus() (or even num_online_cpus()) Using NR_CPUS can lead to extreme waste of memory on kernels which are compiled for 4096 CPUs for example.
And with num_possible_cpus() kmalloc is needed.

OK, new one on me! Thank you for the pointer!

Thanx, Paul

Paul E. McKenney

2008-10-09 11:50 UTC #18 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

In reply to Lai Jiangshan

On Thu, Oct 09, 2008 at 02:20:22PM +0800, Lai Jiangshan wrote:

Thank you for looking this over!

Quoted 1 line

Paul E. McKenney wrote:

[ . . . ]

Quoted 6 lines

Quoted 6 lines
kernel/Kconfig.preempt +0 -0
index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 

Quoted 8 lines

kernel/Kconfig.preempt config PREEMPT_RCU · line 73
Quoted 6 lines
kernel/Kconfig.preempt +0 -1
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help
I think that we can move it to lib/Kconfig.debug.

Makes sense!

[ . . . ]

Quoted 9 lines

kernel/Kconfig.preempt
Quoted 5 lines
kernel/Kconfig.preempt +5 -0
+static int __init rcuclassic_trace_init(void)
+{
+	int ret;
+
+	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
I'm wondering about this. rcuclassic_trace_buf is kmalloc-ed when init module.

Quoted 5 lines

In this case, why not define it as:
static char buf[20*NR_CPUS + 100];
and use it like:
pos += snprintf(buf + cnt, sizeof(buf) - cnt, ...);

I will make Andi's suggested change, both here and in other previously submitted code.

[ . . . ]

Quoted 22 lines

Quoted 8 lines

kernel/Kconfig.preempt +8 -0

+	if (!rcuclassic_trace_buf)
+		return 1;
+	ret = rcuclassic_debugfs_init();
+	if (ret)
+		kfree(rcuclassic_trace_buf);
+	return ret;
+}
+

kernel/Kconfig.preempt

Quoted 10 lines

kernel/Kconfig.preempt +10 -0

+static void __exit rcuclassic_trace_cleanup(void)
+{
+	debugfs_remove(cbdir);
+	debugfs_remove(rcudir);
+	kfree(rcuclassic_trace_buf);
+}
+
+
+module_init(rcuclassic_trace_init);
+module_exit(rcuclassic_trace_cleanup);

I think this trace file shows too little vars for classic rcu.

Quoted 4 lines

It is better that this trace file shows more data.
such as some data in struct rcu_data(quiescent state handling fields, batch, qlen).
or add new files: rcu/rcu_data<cpu#>

Indeed! I will add the ability to dump the rcu_data structures, though I was planning to just dump all of them rather than CPU-by-CPU. (Same approach as in rcutree_trace.c patches.)

Thanx, Paul

Frédéric Weisbecker

2008-10-09 10:23 UTC #19 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

In reply to Frédéric Weisbecker

2008/10/9 Paul E. McKenney <[email protected]>:

Quoted 6 lines

Hello!
This is a tracing patch for Classic RCU, which creates an "rcu/rcucb" file in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.

Quoted 7 lines

Reading from the file results in something like the following:

       rcu: cur=1129  completed=1128  np=0  s=0
               0,3,7
       rcu_bh: cur=-287  completed=-287  np=0  s=0

       online: 0-7

Hi Paul,

Why don't you use the ring-buffer tracing engine?
You will really make your life better by putting it as a tracer in kernel/trace and by using the relevant API.
That will avoid you to manage the debugfs things, the memory allocation, the buffer managment.....

Andi Kleen

author

2008-10-09 10:46 UTC #20 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 1 line

Why don't you use the ring-buffer tracing engine?

Because he doesn't actually need a ring buffer, it's a snapshot in time.

Quoted 4 lines

You will really make your life better by putting it as a tracer in kernel/trace and by using the relevant API.
That will avoid you to manage the debugfs things, the memory allocation, the buffer managment.....

ftrace-of-bork wants to assimilate everything?

-Andi

Signature · 1 line

[email protected]

Frédéric Weisbecker

2008-10-09 11:44 UTC #21 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

2008/10/9 Andi Kleen <[email protected]>:

Quoted 4 lines

Quoted 1 line
Why don't you use the ring-buffer tracing engine?
Because he doesn't actually need a ring buffer, it's a snapshot in time.

You have the possibility to implement a read callback to not use the ring buffer.

Quoted 1 line

ftrace-of-bork wants to assimilate everything?

I just proposed that to unify the tracers.

Paul E. McKenney

2008-10-09 11:54 UTC #22 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

Quoted 16 lines · Frédéric Weisbecker

2008/10/9 Paul E. McKenney <[email protected]>:
Quoted 6 lines
Hello!
This is a tracing patch for Classic RCU, which creates an "rcu/rcucb" file in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.
Quoted 7 lines
Reading from the file results in something like the following:
       rcu: cur=1129  completed=1128  np=0  s=0
               0,3,7
       rcu_bh: cur=-287  completed=-287  np=0  s=0

       online: 0-7

Quoted 7 lines

Hi Paul,
Why don't you use the ring-buffer tracing engine?
You will really make your life better by putting it as a tracer in kernel/trace and by using the relevant API.
That will avoid you to manage the debugfs things, the memory allocation, the buffer managment.....

Hello, Frédéric,

Well, one reason is that I didn't know about it. ;-)

Does it allow the user to trigger a one-shot trace? Right now, what one does is:

cat /debug/rcu/rcucb

whenever one wants to see what RCU is up to. You really don't want to see every new value, as that would generate hundreds of trace records per second -- per CPU. What does the user do with the ring-buffer tracing enging?

Thanx, Paul

Frédéric Weisbecker

2008-10-09 13:02 UTC #23 lore raw

Re: [PATCH] rudimentary tracing for Classic RCU

2008/10/9 Paul E. McKenney <[email protected]>:

Quoted 5 lines

Well, one reason is that I didn't know about it. ;-)
Does it allow the user to trigger a one-shot trace? Right now, what one does is:

Quoted 8 lines

cat /debug/rcu/rcucb
whenever one wants to see what RCU is up to. You really don't want to see every new value, as that would generate hundreds of trace records per second -- per CPU. What does the user do with the ring-buffer tracing enging?
Thanx, Paul

With a tracer from the unified tracing buffer, you have often one function, used somewhere in the kernel, which will add periodically some specific entries. For example mmiotrace receives entries which contain IO access.
When the user tries to read the entries, he has to read the pipe /debug/tracing/trace_pipe. During this reading, the tracing engine calls a read callback given by the tracer. This read callback is nothing related to entries on the buffer: if the tracer has to print something special, this is the ususal function.
Than if the read gave some content, the pipe reading returns. Else, the tracing engine tells the tracer to format its entries from the ring buffer. If there is no entries, the pipe reading sleeps and waits for new entries.

So after some thought, I don't think the current tracing engine is really adapted for what you want. It is a pipe system and it's not adapted for your one-shot captures.

Sorry for the noise.

But it only requires few features to add for the unified tracing engine to support such one-shot tracer.

Paul E. McKenney

2008-10-10 03:44 UTC #24 lore raw

PATCH 1/1 v2 rudimentary tracing for Classic RCU

Hello!

This is a tracing patch for Classic RCU, which creates an "rcu/rcucb" file in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.

Changes since v1: Adds (crude) tracing for rcu_data structures.

Additional work needed: Don't print rcu_data for offline CPUs.
Documentation update.

Reading from the file results in something like the following:

	rcu: cur=1129  completed=1128  np=0  s=0
		0,3,7
	rcu_bh: cur=-287  completed=-287  np=0  s=0

	online: 0-7

The second and fourth lines are a comma/dash-separated list of the CPUs that have not yet reported a quiescent state for the current grace period (CPUs 0, 3, and 7 for "rcu" above).

The last line lists the online CPUs.

Tested on x86 and Power.

---

 include/linux/rcuclassic.h |    3 
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    4 -
 kernel/rcuclassic_trace.c  |  179 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 186 insertions(+), 3 deletions(-)

include/linux/rcuclassic.h +3 -0

index 4ab8436..061a272 100644
@@ -54,6 +54,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {

kernel/Kconfig.preempt +0 -1

index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +2 -2

index aad93cd..517eaa9 100644
@@ -57,13 +57,13 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_bh_ctrlblk.lock),

kernel/rcuclassic_trace.c new file +179 -0

179 lines not on this page · raw message

Paul E. McKenney

2008-10-13 23:09 UTC #25 lore raw

PATCH 1/1 v3 rudimentary tracing for Classic RCU

Hello!

This is v3 of a tracing patch for Classic RCU, which creates "rcu/rcucb" and "rcu/rcudata" files in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.

Should be ready for inclusion in tip/core/rcu, Ingo, please apply.

Changes since v2: Add flag to rcu_data to avoid printing rcu_data for
CPUs that have never been online.

Add documentation (below).

Changes since v1: Adds (crude) tracing for rcu_data structures.

Reading from the "rcu/rcucb" file results in something like the following:

	rcu: cur=1129  completed=1128  pending=0  s=0
		0,3,7
	rcu_bh: cur=-287  completed=-287  pending=0  s=0

	online: 0-7

The first two lines are for rcu, the second two for rcu_bh. The cur= is the current grace-period number, and the completed= is the number of the last completed grace period. If these two numbers are equal, the corresponding flavor of RCU is idle. The pending= is the furthest future batch number that is required, if equal to cur=, no additional grace periods are required. The s=, if non-zero, indicates that a round of reschedule IPIs has been send to attempt to expedite the current grace period.

The second and fourth lines are a comma/dash-separated list of the CPUs that have not yet reported a quiescent state for the current grace period (CPUs 0, 3, and 7 for "rcu" above).

The last line lists the online CPUs.

Reading from the "rcu/rcudata" file results in the following:

	rcu:
	  0 qb=885 b=884 pq=1 qsp=0 ql=0 bl=10
	  1 qb=885 b=882 pq=1 qsp=0 ql=2 bl=10
	  2 qb=885 b=854 pq=1 qsp=0 ql=0 bl=10
	  3 qb=885 b=885 pq=1 qsp=0 ql=0 bl=10
	rcu_bh:
	  0 qb=-291 b=-291 pq=1 qsp=0 ql=0 bl=10
	  1 qb=-291 b=0 pq=1 qsp=0 ql=0 bl=10
	  2 qb=-291 b=0 pq=1 qsp=0 ql=0 bl=10
	  3 qb=-291 b=-298 pq=1 qsp=0 ql=0 bl=10

This output is again split into rcu and rcu_bh portions. Within each portion, there is one line per CPU, but only for those CPUs that have been online at least once since boot. The number at the beginning of each line is the CPU number, followed by an "!" if the corresponding CPU is currently offline. The qb= is the batch number for the RCU core, the b= is the batch number corresponding to the callbacks waiting for the current grace period for this CPU, the pq= is a flag indicating that this CPU has passed through a quiescent state for the current grace period, the qsp= is a flag indicating that the RCU core has been informed that this CPU has passed through a quiescent state for the current grace period, the ql= is the number of RCU callbacks currently enqueued on this CPU (regardless of their state), and the bl= is the current limit of the number of callbacks to be invoked at one shot.

Tested on x86 and Power, rebased to -tip.

---

 include/linux/rcuclassic.h |    4 +
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    5 -
 kernel/rcuclassic_trace.c  |  179 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 188 insertions(+), 3 deletions(-)

include/linux/rcuclassic.h +4 -0

index 5f89b62..ce183a8 100644
@@ -63,6 +63,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {

@@ -81,6 +84,7 @@ struct rcu_data {
 	long		quiescbatch;     /* Batch # for grace period */
 	int		passed_quiesc;	 /* User-mode/idle loop etc. */
 	int		qs_pending;	 /* core waits for quiesc state */
+	bool		beenonline;	 /* CPU online at least once */
 
 	/* 2) batch handling */
 	/*

kernel/Kconfig.preempt +0 -1

index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +3 -2

index 37f72e5..54bd23b 100644
@@ -58,14 +58,14 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.pending = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.pending = -300,

@@ -725,6 +725,7 @@ static void rcu_init_percpu_data(int cpu, struct rcu_ctrlblk *rcp,
 	rdp->donetail = &rdp->donelist;
 	rdp->quiescbatch = rcp->completed;
 	rdp->qs_pending = 0;
+	rdp->beenonline = 1;
 	rdp->cpu = cpu;
 	rdp->blimit = blimit;
 	spin_unlock_irqrestore(&rcp->lock, flags);

kernel/rcuclassic_trace.c new file +179 -0

179 lines not on this page · raw message

Lai Jiangshan

2008-10-14 03:56 UTC #26 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 7 lines · Paul E. McKenney

Hello!
This is v3 of a tracing patch for Classic RCU, which creates "rcu/rcucb" and "rcu/rcudata" files in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.
Should be ready for inclusion in tip/core/rcu, Ingo, please apply.

Hi, Paul,

I'm sorry that I'm a little busy these days, so I have not ported it to seq_file, and you lost one choice.

I found that seq_cpumask_list() is needed when I tried to ported v2 to seq_file, so I introduced seq_cpumask_list() for seq_file, I'm waiting procfs hackers apply that patch too.

Lai.

Quoted 4 lines

Changes since v2: Add flag to rcu_data to avoid printing rcu_data for
CPUs that have never been online.

Quoted 8 lines

Add documentation (below).
Changes since v1: Adds (crude) tracing for rcu_data structures.
Reading from the "rcu/rcucb" file results in something like the following:
	rcu: cur=1129  completed=1128  pending=0  s=0
		0,3,7

use "somename: 0,3,7" ? then when mask is empty, I think "somename:" is better than empty line.

Quoted 216 lines

	rcu_bh: cur=-287  completed=-287  pending=0  s=0

	online: 0-7

The first two lines are for rcu, the second two for rcu_bh. The cur= is the current grace-period number, and the completed= is the number of the last completed grace period. If these two numbers are equal, the corresponding flavor of RCU is idle. The pending= is the furthest future batch number that is required, if equal to cur=, no additional grace periods are required. The s=, if non-zero, indicates that a round of reschedule IPIs has been send to attempt to expedite the current grace period.

The second and fourth lines are a comma/dash-separated list of the CPUs that have not yet reported a quiescent state for the current grace period (CPUs 0, 3, and 7 for "rcu" above).

The last line lists the online CPUs.

Reading from the "rcu/rcudata" file results in the following:

	rcu:
	  0 qb=885 b=884 pq=1 qsp=0 ql=0 bl=10
	  1 qb=885 b=882 pq=1 qsp=0 ql=2 bl=10
	  2 qb=885 b=854 pq=1 qsp=0 ql=0 bl=10
	  3 qb=885 b=885 pq=1 qsp=0 ql=0 bl=10
	rcu_bh:
	  0 qb=-291 b=-291 pq=1 qsp=0 ql=0 bl=10
	  1 qb=-291 b=0 pq=1 qsp=0 ql=0 bl=10
	  2 qb=-291 b=0 pq=1 qsp=0 ql=0 bl=10
	  3 qb=-291 b=-298 pq=1 qsp=0 ql=0 bl=10

Tested on x86 and Power, rebased to -tip.

---

 include/linux/rcuclassic.h |    4 +
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    5 -
 kernel/rcuclassic_trace.c  |  179 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 188 insertions(+), 3 deletions(-)

include/linux/rcuclassic.h +4 -0

index 5f89b62..ce183a8 100644
@@ -63,6 +63,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {

@@ -81,6 +84,7 @@ struct rcu_data {
 	long		quiescbatch;     /* Batch # for grace period */
 	int		passed_quiesc;	 /* User-mode/idle loop etc. */
 	int		qs_pending;	 /* core waits for quiesc state */
+	bool		beenonline;	 /* CPU online at least once */
 
 	/* 2) batch handling */
 	/*

kernel/Kconfig.preempt +0 -1

index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +3 -2

index 37f72e5..54bd23b 100644
@@ -58,14 +58,14 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.pending = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.pending = -300,

@@ -725,6 +725,7 @@ static void rcu_init_percpu_data(int cpu, struct rcu_ctrlblk *rcp,
 	rdp->donetail = &rdp->donelist;
 	rdp->quiescbatch = rcp->completed;
 	rdp->qs_pending = 0;
+	rdp->beenonline = 1;
 	rdp->cpu = cpu;
 	rdp->blimit = blimit;
 	spin_unlock_irqrestore(&rcp->lock, flags);

kernel/rcuclassic_trace.c new file +75 -0

new file mode 100644
index 0000000..d19780b
@@ -0,0 +1,179 @@
+/*
+ * Read-Copy Update tracing for classic implementation
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
+ *
+ * Copyright IBM Corporation, 2008
+ *
+ * Papers:  http://www.rdrop.com/users/paulmck/RCU
+ *
+ * For detailed explanation of Read-Copy Update mechanism see -
+ * 		Documentation/RCU
+ *
+ */
+#include <linux/types.h>
+#include <linux/kernel.h>
+#include <linux/init.h>
+#include <linux/spinlock.h>
+#include <linux/smp.h>
+#include <linux/rcupdate.h>
+#include <linux/interrupt.h>
+#include <linux/sched.h>
+#include <asm/atomic.h>
+#include <linux/bitops.h>
+#include <linux/module.h>
+#include <linux/completion.h>
+#include <linux/moduleparam.h>
+#include <linux/percpu.h>
+#include <linux/notifier.h>
+#include <linux/cpu.h>
+#include <linux/mutex.h>
+#include <linux/debugfs.h>
+
+static DEFINE_MUTEX(rcuclassic_trace_mutex);
+static char *rcuclassic_trace_buf;
+#define RCUCLASSIC_TRACE_BUF_SIZE (128 * num_possible_cpus() + 100)
+
+static int print_one_rcu_data(struct rcu_data *rdp, char *buf, char *ebuf)
+{
+	int cnt = 0;
+
+	if (!rdp->beenonline)
+		return 0;
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt],
+		"%3d%cqb=%ld b=%ld pq=%d qsp=%d ql=%ld bl=%ld\n",
+		rdp->cpu, cpu_is_offline(rdp->cpu) ? '!' : ' ',
+		rdp->quiescbatch, rdp->batch, rdp->passed_quiesc,
+		rdp->qs_pending, rdp->qlen, rdp->blimit);
+	return cnt;
+}
+
+#define PRINT_RCU_DATA(name, buf, ebuf) \
+	do { \
+		int _p_r_d_i; \
+		\
+		for_each_possible_cpu(_p_r_d_i) \
+			(buf) += print_one_rcu_data(&per_cpu(name, _p_r_d_i), \
+						    buf, ebuf); \
+	} while (0)
+
+static ssize_t rcudata_read(struct file *filp, char __user *buffer,
+				size_t count, loff_t *ppos)
+{
+	ssize_t bcount;

kernel/rcuclassic_trace.c line 85

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+	char *buf = rcuclassic_trace_buf;
+	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
+
+	mutex_lock(&rcuclassic_trace_mutex);
+	buf += snprintf(buf, ebuf - buf, "rcu:\n");
+	PRINT_RCU_DATA(rcu_data, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "rcu_bh:\n");
+	PRINT_RCU_DATA(rcu_bh_data, buf, ebuf);
+	bcount = simple_read_from_buffer(buffer, count, ppos,
+			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));

Is strlen(rcuclassic_trace_buf) == buf - rcuclassic_trace_buf ?

Quoted 84 lines

kernel/rcuclassic_trace.c new file +84 -0

+	mutex_unlock(&rcuclassic_trace_mutex);
+	return bcount;
+}
+
+static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+{
+	int cnt = 0;
+
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
+			"pending=%ld  s=%d\n\t",
+			rcp->cur, rcp->completed,
+			rcp->pending, rcp->signaled);
+	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
+	return cnt;
+}
+
+static ssize_t rcucb_read(struct file *filp, char __user *buffer,
+				size_t count, loff_t *ppos)
+{
+	ssize_t bcount;
+	char *buf = rcuclassic_trace_buf;
+	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
+
+	mutex_lock(&rcuclassic_trace_mutex);
+	buf += snprintf(buf, ebuf - buf, "rcu: ");
+	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
+	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "online: ");
+	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
+	buf += snprintf(buf, ebuf - buf, "\n");
+	bcount = simple_read_from_buffer(buffer, count, ppos,
+			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
+	mutex_unlock(&rcuclassic_trace_mutex);
+	return bcount;
+}
+
+static struct file_operations rcudata_fops = {
+	.owner = THIS_MODULE,
+	.read = rcudata_read,
+};
+
+static struct file_operations rcucb_fops = {
+	.owner = THIS_MODULE,
+	.read = rcucb_read,
+};
+
+static struct dentry *rcudir, *datadir, *cbdir;
+static int rcuclassic_debugfs_init(void)
+{
+	rcudir = debugfs_create_dir("rcu", NULL);
+	if (!rcudir)
+		goto out;
+	datadir = debugfs_create_file("rcudata", 0444, rcudir,
+				      NULL, &rcudata_fops);
+	if (!datadir)
+		goto free_out;
+	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
+	if (!cbdir)
+		goto free_out;
+	return 0;
+free_out:
+	if (datadir)
+		debugfs_remove(datadir);
+	debugfs_remove(rcudir);
+out:
+	return 1;
+}
+
+static int __init rcuclassic_trace_init(void)
+{
+	int ret;
+
+	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
+	if (!rcuclassic_trace_buf)
+		return 1;
+	ret = rcuclassic_debugfs_init();
+	if (ret)
+		kfree(rcuclassic_trace_buf);
+	return ret;
+}
+
+static void __exit rcuclassic_trace_cleanup(void)

kernel/rcuclassic_trace.c line 179

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+{
+	debugfs_remove(datadir);
+	debugfs_remove(cbdir);
+	debugfs_remove(rcudir);
+	kfree(rcuclassic_trace_buf);
+}
+
+
+module_init(rcuclassic_trace_init);
+module_exit(rcuclassic_trace_cleanup);

should have:
MODULE_LICENSE("GPL");

optional but recommend:
MODULE_AUTHOR("Paul E. McKenney");
MODULE_DESCRIPTION("DESCRIPTION");

Quoted 8 lines

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Paul E. McKenney

2008-10-14 15:14 UTC #27 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 9 lines · Lai Jiangshan

Quoted 7 lines · Paul E. McKenney
Hello!
This is v3 of a tracing patch for Classic RCU, which creates "rcu/rcucb" and "rcu/rcudata" files in debugfs. This patch can be handy when you need to work out why RCU is refusing to end the current grace period.
Should be ready for inclusion in tip/core/rcu, Ingo, please apply.

Quoted 8 lines

Hi, Paul,
I'm sorry that I'm a little busy these days, so I have not ported it to seq_file, and you lost one choice.
I found that seq_cpumask_list() is needed when I tried to ported v2 to seq_file, so I introduced seq_cpumask_list() for seq_file, I'm waiting procfs hackers apply that patch too.

No problem, will be happy to see your patch whenever it is available.

Thanx, Paul

Quoted 360 lines

Lai.

Quoted 4 lines

Changes since v2: Add flag to rcu_data to avoid printing rcu_data for
CPUs that have never been online.

Quoted 8 lines

Add documentation (below).
Changes since v1: Adds (crude) tracing for rcu_data structures.
Reading from the "rcu/rcucb" file results in something like the following:
	rcu: cur=1129  completed=1128  pending=0  s=0
		0,3,7

use "somename: 0,3,7" ? then when mask is empty, I think "somename:" is better than empty line.

Quoted 216 lines

	rcu_bh: cur=-287  completed=-287  pending=0  s=0

	online: 0-7

The first two lines are for rcu, the second two for rcu_bh. The cur= is the current grace-period number, and the completed= is the number of the last completed grace period. If these two numbers are equal, the corresponding flavor of RCU is idle. The pending= is the furthest future batch number that is required, if equal to cur=, no additional grace periods are required. The s=, if non-zero, indicates that a round of reschedule IPIs has been send to attempt to expedite the current grace period.

The second and fourth lines are a comma/dash-separated list of the CPUs that have not yet reported a quiescent state for the current grace period (CPUs 0, 3, and 7 for "rcu" above).

The last line lists the online CPUs.

Reading from the "rcu/rcudata" file results in the following:

	rcu:
	  0 qb=885 b=884 pq=1 qsp=0 ql=0 bl=10
	  1 qb=885 b=882 pq=1 qsp=0 ql=2 bl=10
	  2 qb=885 b=854 pq=1 qsp=0 ql=0 bl=10
	  3 qb=885 b=885 pq=1 qsp=0 ql=0 bl=10
	rcu_bh:
	  0 qb=-291 b=-291 pq=1 qsp=0 ql=0 bl=10
	  1 qb=-291 b=0 pq=1 qsp=0 ql=0 bl=10
	  2 qb=-291 b=0 pq=1 qsp=0 ql=0 bl=10
	  3 qb=-291 b=-298 pq=1 qsp=0 ql=0 bl=10

Tested on x86 and Power, rebased to -tip.

---

 include/linux/rcuclassic.h |    4 +
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    5 -
 kernel/rcuclassic_trace.c  |  179 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 188 insertions(+), 3 deletions(-)

include/linux/rcuclassic.h +4 -0

index 5f89b62..ce183a8 100644
@@ -63,6 +63,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {

@@ -81,6 +84,7 @@ struct rcu_data {
 	long		quiescbatch;     /* Batch # for grace period */
 	int		passed_quiesc;	 /* User-mode/idle loop etc. */
 	int		qs_pending;	 /* core waits for quiesc state */
+	bool		beenonline;	 /* CPU online at least once */
 
 	/* 2) batch handling */
 	/*

kernel/Kconfig.preempt +0 -1

index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +3 -2

index 37f72e5..54bd23b 100644
@@ -58,14 +58,14 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.pending = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.pending = -300,

@@ -725,6 +725,7 @@ static void rcu_init_percpu_data(int cpu, struct rcu_ctrlblk *rcp,
 	rdp->donetail = &rdp->donelist;
 	rdp->quiescbatch = rcp->completed;
 	rdp->qs_pending = 0;
+	rdp->beenonline = 1;
 	rdp->cpu = cpu;
 	rdp->blimit = blimit;
 	spin_unlock_irqrestore(&rcp->lock, flags);

kernel/rcuclassic_trace.c new file +75 -0

new file mode 100644
index 0000000..d19780b
@@ -0,0 +1,179 @@
+/*
+ * Read-Copy Update tracing for classic implementation
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
+ *
+ * Copyright IBM Corporation, 2008
+ *
+ * Papers:  http://www.rdrop.com/users/paulmck/RCU
+ *
+ * For detailed explanation of Read-Copy Update mechanism see -
+ * 		Documentation/RCU
+ *
+ */
+#include <linux/types.h>
+#include <linux/kernel.h>
+#include <linux/init.h>
+#include <linux/spinlock.h>
+#include <linux/smp.h>
+#include <linux/rcupdate.h>
+#include <linux/interrupt.h>
+#include <linux/sched.h>
+#include <asm/atomic.h>
+#include <linux/bitops.h>
+#include <linux/module.h>
+#include <linux/completion.h>
+#include <linux/moduleparam.h>
+#include <linux/percpu.h>
+#include <linux/notifier.h>
+#include <linux/cpu.h>
+#include <linux/mutex.h>
+#include <linux/debugfs.h>
+
+static DEFINE_MUTEX(rcuclassic_trace_mutex);
+static char *rcuclassic_trace_buf;
+#define RCUCLASSIC_TRACE_BUF_SIZE (128 * num_possible_cpus() + 100)
+
+static int print_one_rcu_data(struct rcu_data *rdp, char *buf, char *ebuf)
+{
+	int cnt = 0;
+
+	if (!rdp->beenonline)
+		return 0;
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt],
+		"%3d%cqb=%ld b=%ld pq=%d qsp=%d ql=%ld bl=%ld\n",
+		rdp->cpu, cpu_is_offline(rdp->cpu) ? '!' : ' ',
+		rdp->quiescbatch, rdp->batch, rdp->passed_quiesc,
+		rdp->qs_pending, rdp->qlen, rdp->blimit);
+	return cnt;
+}
+
+#define PRINT_RCU_DATA(name, buf, ebuf) \
+	do { \
+		int _p_r_d_i; \
+		\
+		for_each_possible_cpu(_p_r_d_i) \
+			(buf) += print_one_rcu_data(&per_cpu(name, _p_r_d_i), \
+						    buf, ebuf); \
+	} while (0)
+
+static ssize_t rcudata_read(struct file *filp, char __user *buffer,
+				size_t count, loff_t *ppos)
+{
+	ssize_t bcount;

kernel/rcuclassic_trace.c line 85

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+	char *buf = rcuclassic_trace_buf;
+	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
+
+	mutex_lock(&rcuclassic_trace_mutex);
+	buf += snprintf(buf, ebuf - buf, "rcu:\n");
+	PRINT_RCU_DATA(rcu_data, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "rcu_bh:\n");
+	PRINT_RCU_DATA(rcu_bh_data, buf, ebuf);
+	bcount = simple_read_from_buffer(buffer, count, ppos,
+			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));

Is strlen(rcuclassic_trace_buf) == buf - rcuclassic_trace_buf ?

Quoted 84 lines

kernel/rcuclassic_trace.c new file +84 -0

+	mutex_unlock(&rcuclassic_trace_mutex);
+	return bcount;
+}
+
+static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+{
+	int cnt = 0;
+
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
+			"pending=%ld  s=%d\n\t",
+			rcp->cur, rcp->completed,
+			rcp->pending, rcp->signaled);
+	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
+	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
+	return cnt;
+}
+
+static ssize_t rcucb_read(struct file *filp, char __user *buffer,
+				size_t count, loff_t *ppos)
+{
+	ssize_t bcount;
+	char *buf = rcuclassic_trace_buf;
+	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
+
+	mutex_lock(&rcuclassic_trace_mutex);
+	buf += snprintf(buf, ebuf - buf, "rcu: ");
+	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
+	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
+	buf += snprintf(buf, ebuf - buf, "online: ");
+	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
+	buf += snprintf(buf, ebuf - buf, "\n");
+	bcount = simple_read_from_buffer(buffer, count, ppos,
+			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
+	mutex_unlock(&rcuclassic_trace_mutex);
+	return bcount;
+}
+
+static struct file_operations rcudata_fops = {
+	.owner = THIS_MODULE,
+	.read = rcudata_read,
+};
+
+static struct file_operations rcucb_fops = {
+	.owner = THIS_MODULE,
+	.read = rcucb_read,
+};
+
+static struct dentry *rcudir, *datadir, *cbdir;
+static int rcuclassic_debugfs_init(void)
+{
+	rcudir = debugfs_create_dir("rcu", NULL);
+	if (!rcudir)
+		goto out;
+	datadir = debugfs_create_file("rcudata", 0444, rcudir,
+				      NULL, &rcudata_fops);
+	if (!datadir)
+		goto free_out;
+	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
+	if (!cbdir)
+		goto free_out;
+	return 0;
+free_out:
+	if (datadir)
+		debugfs_remove(datadir);
+	debugfs_remove(rcudir);
+out:
+	return 1;
+}
+
+static int __init rcuclassic_trace_init(void)
+{
+	int ret;
+
+	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
+	if (!rcuclassic_trace_buf)
+		return 1;
+	ret = rcuclassic_debugfs_init();
+	if (ret)
+		kfree(rcuclassic_trace_buf);
+	return ret;
+}
+
+static void __exit rcuclassic_trace_cleanup(void)

kernel/rcuclassic_trace.c line 179

Quoted 10 lines

kernel/rcuclassic_trace.c new file +10 -0

+{
+	debugfs_remove(datadir);
+	debugfs_remove(cbdir);
+	debugfs_remove(rcudir);
+	kfree(rcuclassic_trace_buf);
+}
+
+
+module_init(rcuclassic_trace_init);
+module_exit(rcuclassic_trace_cleanup);

should have:
MODULE_LICENSE("GPL");

optional but recommend:
MODULE_AUTHOR("Paul E. McKenney");
MODULE_DESCRIPTION("DESCRIPTION");

Quoted 8 lines

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Lai Jiangshan

2008-10-23 11:15 UTC #28 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

trivial ported it to seq_file.
seq_file are very good for the output buffer.

---

kernel/rcuclassic_trace.c +122 ~~-112~~

index d19780b..f19217c
@@ -23,157 +23,167 @@
  * 		Documentation/RCU
  *
  */
-#include <linux/types.h>
-#include <linux/kernel.h>
-#include <linux/init.h>
-#include <linux/spinlock.h>
-#include <linux/smp.h>
 #include <linux/rcupdate.h>
-#include <linux/interrupt.h>
-#include <linux/sched.h>
-#include <asm/atomic.h>
-#include <linux/bitops.h>
 #include <linux/module.h>
-#include <linux/completion.h>
-#include <linux/moduleparam.h>
-#include <linux/percpu.h>
-#include <linux/notifier.h>
-#include <linux/cpu.h>
-#include <linux/mutex.h>
 #include <linux/debugfs.h>
+#include <linux/seq_file.h>
 
-static DEFINE_MUTEX(rcuclassic_trace_mutex);
-static char *rcuclassic_trace_buf;
-#define RCUCLASSIC_TRACE_BUF_SIZE (128 * num_possible_cpus() + 100)
+static struct rcu_data *get_rcu_data_bh(int cpu)
+{
+	return &per_cpu(rcu_bh_data, cpu);
+}
 
-static int print_one_rcu_data(struct rcu_data *rdp, char *buf, char *ebuf)
+static struct rcu_data *get_rcu_data(int cpu)
 {
-	int cnt = 0;
+	return &per_cpu(rcu_data, cpu);
+}
 
+static int show_rcu_data(struct seq_file *m, void *v)
+{
+	struct rcu_data *rdp = v;
 	if (!rdp->beenonline)
 		return 0;
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt],
-		"%3d%cqb=%ld b=%ld pq=%d qsp=%d ql=%ld bl=%ld\n",
-		rdp->cpu, cpu_is_offline(rdp->cpu) ? '!' : ' ',
-		rdp->quiescbatch, rdp->batch, rdp->passed_quiesc,
-		rdp->qs_pending, rdp->qlen, rdp->blimit);
-	return cnt;
+
+	seq_printf(m, "processor\t: %d", rdp->cpu);
+	if (cpu_is_offline(rdp->cpu))
+		seq_puts(m, "!\n");
+	else
+		seq_puts(m, "\n");
+	seq_printf(m, "quiescbatch\t: %ld\n", rdp->quiescbatch);
+	seq_printf(m, "batch\t: %ld\n", rdp->batch);
+	seq_printf(m, "passed_quiesc\t: %d\n", rdp->passed_quiesc);
+	seq_printf(m, "qs_pending\t: %d\n", rdp->qs_pending);
+	seq_printf(m, "qlen\t: %ld\n", rdp->qlen);
+	seq_printf(m, "blimit\t: %ld\n", rdp->blimit);
+	seq_puts(m, "\n\n");
+	return 0;
 }
 
-#define PRINT_RCU_DATA(name, buf, ebuf) \
-	do { \
-		int _p_r_d_i; \
-		\
-		for_each_possible_cpu(_p_r_d_i) \
-			(buf) += print_one_rcu_data(&per_cpu(name, _p_r_d_i), \
-						    buf, ebuf); \
-	} while (0)
-
-static ssize_t rcudata_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void *c_start(struct seq_file *m, loff_t *pos)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu:\n");
-	PRINT_RCU_DATA(rcu_data, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh:\n");
-	PRINT_RCU_DATA(rcu_bh_data, buf, ebuf);
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
+	typedef struct rcu_data *(*get_data_func)(int);
+
+	if (*pos == 0)	/* just in case, cpu 0 is not the first */
+		*pos = first_cpu(cpu_possible_map);
+	else
+		*pos = next_cpu_nr(*pos - 1, cpu_possible_map);
+	if ((*pos) < nr_cpu_ids)
+		return ((get_data_func)m->private)(*pos);
+	return NULL;
 }
 
-static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+static void *c_next(struct seq_file *m, void *v, loff_t *pos)
 {
-	int cnt = 0;
-
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
-			"pending=%ld  s=%d\n\t",
-			rcp->cur, rcp->completed,
-			rcp->pending, rcp->signaled);
-	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
-	return cnt;
+	(*pos)++;
+	return c_start(m, pos);
 }
 
-static ssize_t rcucb_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void c_stop(struct seq_file *m, void *v)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu: ");
-	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
-	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "online: ");
-	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
-	buf += snprintf(buf, ebuf - buf, "\n");
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
 }
 
-static struct file_operations rcudata_fops = {
-	.owner = THIS_MODULE,
-	.read = rcudata_read,
+const struct seq_operations rcu_data_seq_op = {
+	.start	= c_start,
+	.next	= c_next,
+	.stop	= c_stop,
+	.show	= show_rcu_data,
 };
 
+static int rcu_data_open(struct inode *inode, struct file *file)
+{
+	int ret = seq_open(file, &rcu_data_seq_op);
+	if (ret)
+		return ret;
+	((struct seq_file *)file->private_data)->private = inode->i_private;
+	return 0;
+}
+
+static const struct file_operations rcu_data_fops = {
+	.owner		= THIS_MODULE,
+	.open		= rcu_data_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= seq_release,
+};
+
+static void print_one_rcu_ctrlblk(struct seq_file *m, struct rcu_ctrlblk *rcp)
+{
+	seq_printf(m, "cur=%ld  completed=%ld   pending=%ld  s=%d\n\t",
+			rcp->cur, rcp->completed, rcp->pending, rcp->signaled);
+	seq_cpumask(m, &rcp->cpumask);
+	seq_puts(m, "\n");
+}
+
+static int show_rcucb(struct seq_file *m, void *unused)
+{
+	seq_puts(m, "rcu: ");
+	print_one_rcu_ctrlblk(m, &rcu_ctrlblk);
+	seq_puts(m, "rcu_bh: ");
+	print_one_rcu_ctrlblk(m, &rcu_bh_ctrlblk);
+	seq_puts(m, "online: ");
+	seq_cpumask(m, &cpu_online_map);
+	seq_puts(m, "\n");
+	return 0;
+}
+
+static int rcucb_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, show_rcucb, NULL);
+}
+
 static struct file_operations rcucb_fops = {
-	.owner = THIS_MODULE,
-	.read = rcucb_read,
+	.owner		= THIS_MODULE,
+	.open		= rcucb_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= single_release,
 };
 
-static struct dentry *rcudir, *datadir, *cbdir;
-static int rcuclassic_debugfs_init(void)
+static struct dentry *rcudir, *rcu_bh_data_file, *rcu_data_file, *rcucb_file;
+
+static int __init rcuclassic_trace_init(void)
 {
 	rcudir = debugfs_create_dir("rcu", NULL);
 	if (!rcudir)
 		goto out;
-	datadir = debugfs_create_file("rcudata", 0444, rcudir,
-				      NULL, &rcudata_fops);
-	if (!datadir)
-		goto free_out;
-	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
-	if (!cbdir)
-		goto free_out;
+
+	rcu_bh_data_file = debugfs_create_file("rcu_bh_data", 0444, rcudir,
+			get_rcu_data_bh, &rcu_data_fops);
+	if (!rcu_bh_data_file)
+		goto out_rcudir;
+
+	rcu_data_file = debugfs_create_file("rcu_data", 0444, rcudir,
+			get_rcu_data, &rcu_data_fops);
+	if (!rcu_data_file)
+		goto out_rcudata_bh_file;
+
+	rcucb_file = debugfs_create_file("rcucb", 0444, rcudir,
+			NULL, &rcucb_fops);
+	if (!rcucb_file)
+		goto out_rcudata_file;
 	return 0;
-free_out:
-	if (datadir)
-		debugfs_remove(datadir);
+
+out_rcudata_file:
+	debugfs_remove(rcu_data_file);
+out_rcudata_bh_file:
+	debugfs_remove(rcu_bh_data_file);
+out_rcudir:
 	debugfs_remove(rcudir);
 out:
 	return 1;
 }
 
-static int __init rcuclassic_trace_init(void)
-{
-	int ret;
-
-	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
-	if (!rcuclassic_trace_buf)
-		return 1;
-	ret = rcuclassic_debugfs_init();
-	if (ret)
-		kfree(rcuclassic_trace_buf);
-	return ret;
-}
-
 static void __exit rcuclassic_trace_cleanup(void)
 {
-	debugfs_remove(datadir);
-	debugfs_remove(cbdir);
+	debugfs_remove(rcucb_file);
+	debugfs_remove(rcu_data_file);
+	debugfs_remove(rcu_bh_data_file);
 	debugfs_remove(rcudir);
-	kfree(rcuclassic_trace_buf);
 }
 
-
 module_init(rcuclassic_trace_init);
 module_exit(rcuclassic_trace_cleanup);
+
+MODULE_AUTHOR("Paul E. McKenney");
+MODULE_DESCRIPTION("Read-Copy Update tracing for classic implementation");
+MODULE_LICENSE("GPL");

Paul E. McKenney

2008-10-27 05:28 UTC #29 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 3 lines · Lai Jiangshan

trivial ported it to seq_file.
seq_file are very good for the output buffer.

Thank you for putting this together!!! Looks good at first glance -- I will test it out.

Thanx, Paul

Quoted 287 lines

---

kernel/rcuclassic_trace.c +122 ~~-112~~

index d19780b..f19217c
@@ -23,157 +23,167 @@
  * 		Documentation/RCU
  *
  */
-#include <linux/types.h>
-#include <linux/kernel.h>
-#include <linux/init.h>
-#include <linux/spinlock.h>
-#include <linux/smp.h>
 #include <linux/rcupdate.h>
-#include <linux/interrupt.h>
-#include <linux/sched.h>
-#include <asm/atomic.h>
-#include <linux/bitops.h>
 #include <linux/module.h>
-#include <linux/completion.h>
-#include <linux/moduleparam.h>
-#include <linux/percpu.h>
-#include <linux/notifier.h>
-#include <linux/cpu.h>
-#include <linux/mutex.h>
 #include <linux/debugfs.h>
+#include <linux/seq_file.h>
 
-static DEFINE_MUTEX(rcuclassic_trace_mutex);
-static char *rcuclassic_trace_buf;
-#define RCUCLASSIC_TRACE_BUF_SIZE (128 * num_possible_cpus() + 100)
+static struct rcu_data *get_rcu_data_bh(int cpu)
+{
+	return &per_cpu(rcu_bh_data, cpu);
+}
 
-static int print_one_rcu_data(struct rcu_data *rdp, char *buf, char *ebuf)
+static struct rcu_data *get_rcu_data(int cpu)
 {
-	int cnt = 0;
+	return &per_cpu(rcu_data, cpu);
+}
 
+static int show_rcu_data(struct seq_file *m, void *v)
+{
+	struct rcu_data *rdp = v;
 	if (!rdp->beenonline)
 		return 0;
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt],
-		"%3d%cqb=%ld b=%ld pq=%d qsp=%d ql=%ld bl=%ld\n",
-		rdp->cpu, cpu_is_offline(rdp->cpu) ? '!' : ' ',
-		rdp->quiescbatch, rdp->batch, rdp->passed_quiesc,
-		rdp->qs_pending, rdp->qlen, rdp->blimit);
-	return cnt;
+
+	seq_printf(m, "processor\t: %d", rdp->cpu);
+	if (cpu_is_offline(rdp->cpu))
+		seq_puts(m, "!\n");
+	else
+		seq_puts(m, "\n");
+	seq_printf(m, "quiescbatch\t: %ld\n", rdp->quiescbatch);
+	seq_printf(m, "batch\t: %ld\n", rdp->batch);
+	seq_printf(m, "passed_quiesc\t: %d\n", rdp->passed_quiesc);
+	seq_printf(m, "qs_pending\t: %d\n", rdp->qs_pending);
+	seq_printf(m, "qlen\t: %ld\n", rdp->qlen);
+	seq_printf(m, "blimit\t: %ld\n", rdp->blimit);
+	seq_puts(m, "\n\n");
+	return 0;
 }
 
-#define PRINT_RCU_DATA(name, buf, ebuf) \
-	do { \
-		int _p_r_d_i; \
-		\
-		for_each_possible_cpu(_p_r_d_i) \
-			(buf) += print_one_rcu_data(&per_cpu(name, _p_r_d_i), \
-						    buf, ebuf); \
-	} while (0)
-
-static ssize_t rcudata_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void *c_start(struct seq_file *m, loff_t *pos)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu:\n");
-	PRINT_RCU_DATA(rcu_data, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh:\n");
-	PRINT_RCU_DATA(rcu_bh_data, buf, ebuf);
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
+	typedef struct rcu_data *(*get_data_func)(int);
+
+	if (*pos == 0)	/* just in case, cpu 0 is not the first */
+		*pos = first_cpu(cpu_possible_map);
+	else
+		*pos = next_cpu_nr(*pos - 1, cpu_possible_map);
+	if ((*pos) < nr_cpu_ids)
+		return ((get_data_func)m->private)(*pos);
+	return NULL;
 }
 
-static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+static void *c_next(struct seq_file *m, void *v, loff_t *pos)
 {
-	int cnt = 0;
-
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
-			"pending=%ld  s=%d\n\t",
-			rcp->cur, rcp->completed,
-			rcp->pending, rcp->signaled);
-	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
-	return cnt;
+	(*pos)++;
+	return c_start(m, pos);
 }
 
-static ssize_t rcucb_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void c_stop(struct seq_file *m, void *v)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu: ");
-	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
-	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "online: ");
-	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
-	buf += snprintf(buf, ebuf - buf, "\n");
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
 }
 
-static struct file_operations rcudata_fops = {
-	.owner = THIS_MODULE,
-	.read = rcudata_read,
+const struct seq_operations rcu_data_seq_op = {
+	.start	= c_start,
+	.next	= c_next,
+	.stop	= c_stop,
+	.show	= show_rcu_data,
 };
 
+static int rcu_data_open(struct inode *inode, struct file *file)
+{
+	int ret = seq_open(file, &rcu_data_seq_op);
+	if (ret)
+		return ret;
+	((struct seq_file *)file->private_data)->private = inode->i_private;
+	return 0;
+}
+
+static const struct file_operations rcu_data_fops = {
+	.owner		= THIS_MODULE,
+	.open		= rcu_data_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= seq_release,
+};
+
+static void print_one_rcu_ctrlblk(struct seq_file *m, struct rcu_ctrlblk *rcp)
+{
+	seq_printf(m, "cur=%ld  completed=%ld   pending=%ld  s=%d\n\t",
+			rcp->cur, rcp->completed, rcp->pending, rcp->signaled);
+	seq_cpumask(m, &rcp->cpumask);
+	seq_puts(m, "\n");
+}
+
+static int show_rcucb(struct seq_file *m, void *unused)
+{
+	seq_puts(m, "rcu: ");
+	print_one_rcu_ctrlblk(m, &rcu_ctrlblk);
+	seq_puts(m, "rcu_bh: ");
+	print_one_rcu_ctrlblk(m, &rcu_bh_ctrlblk);
+	seq_puts(m, "online: ");
+	seq_cpumask(m, &cpu_online_map);
+	seq_puts(m, "\n");
+	return 0;
+}
+
+static int rcucb_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, show_rcucb, NULL);
+}
+
 static struct file_operations rcucb_fops = {
-	.owner = THIS_MODULE,
-	.read = rcucb_read,
+	.owner		= THIS_MODULE,
+	.open		= rcucb_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= single_release,
 };
 
-static struct dentry *rcudir, *datadir, *cbdir;
-static int rcuclassic_debugfs_init(void)
+static struct dentry *rcudir, *rcu_bh_data_file, *rcu_data_file, *rcucb_file;
+
+static int __init rcuclassic_trace_init(void)
 {
 	rcudir = debugfs_create_dir("rcu", NULL);
 	if (!rcudir)
 		goto out;
-	datadir = debugfs_create_file("rcudata", 0444, rcudir,
-				      NULL, &rcudata_fops);
-	if (!datadir)
-		goto free_out;
-	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
-	if (!cbdir)
-		goto free_out;
+
+	rcu_bh_data_file = debugfs_create_file("rcu_bh_data", 0444, rcudir,
+			get_rcu_data_bh, &rcu_data_fops);
+	if (!rcu_bh_data_file)
+		goto out_rcudir;
+
+	rcu_data_file = debugfs_create_file("rcu_data", 0444, rcudir,
+			get_rcu_data, &rcu_data_fops);
+	if (!rcu_data_file)
+		goto out_rcudata_bh_file;
+
+	rcucb_file = debugfs_create_file("rcucb", 0444, rcudir,
+			NULL, &rcucb_fops);
+	if (!rcucb_file)
+		goto out_rcudata_file;
 	return 0;
-free_out:
-	if (datadir)
-		debugfs_remove(datadir);
+
+out_rcudata_file:
+	debugfs_remove(rcu_data_file);
+out_rcudata_bh_file:
+	debugfs_remove(rcu_bh_data_file);
+out_rcudir:
 	debugfs_remove(rcudir);
 out:
 	return 1;
 }
 
-static int __init rcuclassic_trace_init(void)
-{
-	int ret;
-
-	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
-	if (!rcuclassic_trace_buf)
-		return 1;
-	ret = rcuclassic_debugfs_init();
-	if (ret)
-		kfree(rcuclassic_trace_buf);
-	return ret;
-}
-
 static void __exit rcuclassic_trace_cleanup(void)
 {
-	debugfs_remove(datadir);
-	debugfs_remove(cbdir);
+	debugfs_remove(rcucb_file);
+	debugfs_remove(rcu_data_file);
+	debugfs_remove(rcu_bh_data_file);
 	debugfs_remove(rcudir);
-	kfree(rcuclassic_trace_buf);
 }
 
-
 module_init(rcuclassic_trace_init);
 module_exit(rcuclassic_trace_cleanup);
+
+MODULE_AUTHOR("Paul E. McKenney");
+MODULE_DESCRIPTION("Read-Copy Update tracing for classic implementation");
+MODULE_LICENSE("GPL");

Paul E. McKenney

2008-10-27 21:50 UTC #30 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 7 lines · Paul E. McKenney

Quoted 3 lines · Lai Jiangshan
trivial ported it to seq_file.
seq_file are very good for the output buffer.
Thank you for putting this together!!! Looks good at first glance -- I will test it out.

So it does seem to operate correctly. I combined it with my patch and applied against 2.6.27 for ease of testing.

One question -- why the multi-line format? This would be a bit awkward on a 128-CPU system, let alone on a 4,096-CPU system. Or am I missing some trick here?

Quoted 289 lines

Thanx, Paul

Quoted 287 lines

---

kernel/rcuclassic_trace.c +122 ~~-112~~

index d19780b..f19217c
@@ -23,157 +23,167 @@
  * 		Documentation/RCU
  *
  */
-#include <linux/types.h>
-#include <linux/kernel.h>
-#include <linux/init.h>
-#include <linux/spinlock.h>
-#include <linux/smp.h>
 #include <linux/rcupdate.h>
-#include <linux/interrupt.h>
-#include <linux/sched.h>
-#include <asm/atomic.h>
-#include <linux/bitops.h>
 #include <linux/module.h>
-#include <linux/completion.h>
-#include <linux/moduleparam.h>
-#include <linux/percpu.h>
-#include <linux/notifier.h>
-#include <linux/cpu.h>
-#include <linux/mutex.h>
 #include <linux/debugfs.h>
+#include <linux/seq_file.h>
 
-static DEFINE_MUTEX(rcuclassic_trace_mutex);
-static char *rcuclassic_trace_buf;
-#define RCUCLASSIC_TRACE_BUF_SIZE (128 * num_possible_cpus() + 100)
+static struct rcu_data *get_rcu_data_bh(int cpu)
+{
+	return &per_cpu(rcu_bh_data, cpu);
+}
 
-static int print_one_rcu_data(struct rcu_data *rdp, char *buf, char *ebuf)
+static struct rcu_data *get_rcu_data(int cpu)
 {
-	int cnt = 0;
+	return &per_cpu(rcu_data, cpu);
+}
 
+static int show_rcu_data(struct seq_file *m, void *v)
+{
+	struct rcu_data *rdp = v;
 	if (!rdp->beenonline)
 		return 0;
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt],
-		"%3d%cqb=%ld b=%ld pq=%d qsp=%d ql=%ld bl=%ld\n",
-		rdp->cpu, cpu_is_offline(rdp->cpu) ? '!' : ' ',
-		rdp->quiescbatch, rdp->batch, rdp->passed_quiesc,
-		rdp->qs_pending, rdp->qlen, rdp->blimit);
-	return cnt;
+
+	seq_printf(m, "processor\t: %d", rdp->cpu);
+	if (cpu_is_offline(rdp->cpu))
+		seq_puts(m, "!\n");
+	else
+		seq_puts(m, "\n");
+	seq_printf(m, "quiescbatch\t: %ld\n", rdp->quiescbatch);
+	seq_printf(m, "batch\t: %ld\n", rdp->batch);
+	seq_printf(m, "passed_quiesc\t: %d\n", rdp->passed_quiesc);
+	seq_printf(m, "qs_pending\t: %d\n", rdp->qs_pending);
+	seq_printf(m, "qlen\t: %ld\n", rdp->qlen);
+	seq_printf(m, "blimit\t: %ld\n", rdp->blimit);
+	seq_puts(m, "\n\n");
+	return 0;
 }
 
-#define PRINT_RCU_DATA(name, buf, ebuf) \
-	do { \
-		int _p_r_d_i; \
-		\
-		for_each_possible_cpu(_p_r_d_i) \
-			(buf) += print_one_rcu_data(&per_cpu(name, _p_r_d_i), \
-						    buf, ebuf); \
-	} while (0)
-
-static ssize_t rcudata_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void *c_start(struct seq_file *m, loff_t *pos)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu:\n");
-	PRINT_RCU_DATA(rcu_data, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh:\n");
-	PRINT_RCU_DATA(rcu_bh_data, buf, ebuf);
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
+	typedef struct rcu_data *(*get_data_func)(int);
+
+	if (*pos == 0)	/* just in case, cpu 0 is not the first */
+		*pos = first_cpu(cpu_possible_map);
+	else
+		*pos = next_cpu_nr(*pos - 1, cpu_possible_map);
+	if ((*pos) < nr_cpu_ids)
+		return ((get_data_func)m->private)(*pos);
+	return NULL;
 }
 
-static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+static void *c_next(struct seq_file *m, void *v, loff_t *pos)
 {
-	int cnt = 0;
-
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
-			"pending=%ld  s=%d\n\t",
-			rcp->cur, rcp->completed,
-			rcp->pending, rcp->signaled);
-	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
-	return cnt;
+	(*pos)++;
+	return c_start(m, pos);
 }
 
-static ssize_t rcucb_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void c_stop(struct seq_file *m, void *v)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu: ");
-	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
-	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "online: ");
-	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
-	buf += snprintf(buf, ebuf - buf, "\n");
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
 }
 
-static struct file_operations rcudata_fops = {
-	.owner = THIS_MODULE,
-	.read = rcudata_read,
+const struct seq_operations rcu_data_seq_op = {
+	.start	= c_start,
+	.next	= c_next,
+	.stop	= c_stop,
+	.show	= show_rcu_data,
 };
 
+static int rcu_data_open(struct inode *inode, struct file *file)
+{
+	int ret = seq_open(file, &rcu_data_seq_op);
+	if (ret)
+		return ret;
+	((struct seq_file *)file->private_data)->private = inode->i_private;
+	return 0;
+}
+
+static const struct file_operations rcu_data_fops = {
+	.owner		= THIS_MODULE,
+	.open		= rcu_data_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= seq_release,
+};
+
+static void print_one_rcu_ctrlblk(struct seq_file *m, struct rcu_ctrlblk *rcp)
+{
+	seq_printf(m, "cur=%ld  completed=%ld   pending=%ld  s=%d\n\t",
+			rcp->cur, rcp->completed, rcp->pending, rcp->signaled);
+	seq_cpumask(m, &rcp->cpumask);
+	seq_puts(m, "\n");
+}
+
+static int show_rcucb(struct seq_file *m, void *unused)
+{
+	seq_puts(m, "rcu: ");
+	print_one_rcu_ctrlblk(m, &rcu_ctrlblk);
+	seq_puts(m, "rcu_bh: ");
+	print_one_rcu_ctrlblk(m, &rcu_bh_ctrlblk);
+	seq_puts(m, "online: ");
+	seq_cpumask(m, &cpu_online_map);
+	seq_puts(m, "\n");
+	return 0;
+}
+
+static int rcucb_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, show_rcucb, NULL);
+}
+
 static struct file_operations rcucb_fops = {
-	.owner = THIS_MODULE,
-	.read = rcucb_read,
+	.owner		= THIS_MODULE,
+	.open		= rcucb_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= single_release,
 };
 
-static struct dentry *rcudir, *datadir, *cbdir;
-static int rcuclassic_debugfs_init(void)
+static struct dentry *rcudir, *rcu_bh_data_file, *rcu_data_file, *rcucb_file;
+
+static int __init rcuclassic_trace_init(void)
 {
 	rcudir = debugfs_create_dir("rcu", NULL);
 	if (!rcudir)
 		goto out;
-	datadir = debugfs_create_file("rcudata", 0444, rcudir,
-				      NULL, &rcudata_fops);
-	if (!datadir)
-		goto free_out;
-	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
-	if (!cbdir)
-		goto free_out;
+
+	rcu_bh_data_file = debugfs_create_file("rcu_bh_data", 0444, rcudir,
+			get_rcu_data_bh, &rcu_data_fops);
+	if (!rcu_bh_data_file)
+		goto out_rcudir;
+
+	rcu_data_file = debugfs_create_file("rcu_data", 0444, rcudir,
+			get_rcu_data, &rcu_data_fops);
+	if (!rcu_data_file)
+		goto out_rcudata_bh_file;
+
+	rcucb_file = debugfs_create_file("rcucb", 0444, rcudir,
+			NULL, &rcucb_fops);
+	if (!rcucb_file)
+		goto out_rcudata_file;
 	return 0;
-free_out:
-	if (datadir)
-		debugfs_remove(datadir);
+
+out_rcudata_file:
+	debugfs_remove(rcu_data_file);
+out_rcudata_bh_file:
+	debugfs_remove(rcu_bh_data_file);
+out_rcudir:
 	debugfs_remove(rcudir);
 out:
 	return 1;
 }
 
-static int __init rcuclassic_trace_init(void)
-{
-	int ret;
-
-	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
-	if (!rcuclassic_trace_buf)
-		return 1;
-	ret = rcuclassic_debugfs_init();
-	if (ret)
-		kfree(rcuclassic_trace_buf);
-	return ret;
-}
-
 static void __exit rcuclassic_trace_cleanup(void)
 {
-	debugfs_remove(datadir);
-	debugfs_remove(cbdir);
+	debugfs_remove(rcucb_file);
+	debugfs_remove(rcu_data_file);
+	debugfs_remove(rcu_bh_data_file);
 	debugfs_remove(rcudir);
-	kfree(rcuclassic_trace_buf);
 }
 
-
 module_init(rcuclassic_trace_init);
 module_exit(rcuclassic_trace_cleanup);
+
+MODULE_AUTHOR("Paul E. McKenney");
+MODULE_DESCRIPTION("Read-Copy Update tracing for classic implementation");
+MODULE_LICENSE("GPL");

Paul E. McKenney

2008-10-27 23:57 UTC #31 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 9 lines · Paul E. McKenney

Quoted 7 lines · Paul E. McKenney
Quoted 3 lines · Lai Jiangshan
trivial ported it to seq_file.
seq_file are very good for the output buffer.
Thank you for putting this together!!! Looks good at first glance -- I will test it out.

Quoted 6 lines

So it does seem to operate correctly. I combined it with my patch and applied against 2.6.27 for ease of testing.
One question -- why the multi-line format? This would be a bit awkward on a 128-CPU system, let alone on a 4,096-CPU system. Or am I missing some trick here?

To clarify, by "missing some trick", I am wondering if there is some command that works in blocks of lines. After all, /proc/cpuinfo produces the same sort of output that your patch does. ;-)

Thanx, Paul

Quoted 287 lines

---

kernel/rcuclassic_trace.c +122 ~~-112~~

index d19780b..f19217c
@@ -23,157 +23,167 @@
  * 		Documentation/RCU
  *
  */
-#include <linux/types.h>
-#include <linux/kernel.h>
-#include <linux/init.h>
-#include <linux/spinlock.h>
-#include <linux/smp.h>
 #include <linux/rcupdate.h>
-#include <linux/interrupt.h>
-#include <linux/sched.h>
-#include <asm/atomic.h>
-#include <linux/bitops.h>
 #include <linux/module.h>
-#include <linux/completion.h>
-#include <linux/moduleparam.h>
-#include <linux/percpu.h>
-#include <linux/notifier.h>
-#include <linux/cpu.h>
-#include <linux/mutex.h>
 #include <linux/debugfs.h>
+#include <linux/seq_file.h>
 
-static DEFINE_MUTEX(rcuclassic_trace_mutex);
-static char *rcuclassic_trace_buf;
-#define RCUCLASSIC_TRACE_BUF_SIZE (128 * num_possible_cpus() + 100)
+static struct rcu_data *get_rcu_data_bh(int cpu)
+{
+	return &per_cpu(rcu_bh_data, cpu);
+}
 
-static int print_one_rcu_data(struct rcu_data *rdp, char *buf, char *ebuf)
+static struct rcu_data *get_rcu_data(int cpu)
 {
-	int cnt = 0;
+	return &per_cpu(rcu_data, cpu);
+}
 
+static int show_rcu_data(struct seq_file *m, void *v)
+{
+	struct rcu_data *rdp = v;
 	if (!rdp->beenonline)
 		return 0;
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt],
-		"%3d%cqb=%ld b=%ld pq=%d qsp=%d ql=%ld bl=%ld\n",
-		rdp->cpu, cpu_is_offline(rdp->cpu) ? '!' : ' ',
-		rdp->quiescbatch, rdp->batch, rdp->passed_quiesc,
-		rdp->qs_pending, rdp->qlen, rdp->blimit);
-	return cnt;
+
+	seq_printf(m, "processor\t: %d", rdp->cpu);
+	if (cpu_is_offline(rdp->cpu))
+		seq_puts(m, "!\n");
+	else
+		seq_puts(m, "\n");
+	seq_printf(m, "quiescbatch\t: %ld\n", rdp->quiescbatch);
+	seq_printf(m, "batch\t: %ld\n", rdp->batch);
+	seq_printf(m, "passed_quiesc\t: %d\n", rdp->passed_quiesc);
+	seq_printf(m, "qs_pending\t: %d\n", rdp->qs_pending);
+	seq_printf(m, "qlen\t: %ld\n", rdp->qlen);
+	seq_printf(m, "blimit\t: %ld\n", rdp->blimit);
+	seq_puts(m, "\n\n");
+	return 0;
 }
 
-#define PRINT_RCU_DATA(name, buf, ebuf) \
-	do { \
-		int _p_r_d_i; \
-		\
-		for_each_possible_cpu(_p_r_d_i) \
-			(buf) += print_one_rcu_data(&per_cpu(name, _p_r_d_i), \
-						    buf, ebuf); \
-	} while (0)
-
-static ssize_t rcudata_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void *c_start(struct seq_file *m, loff_t *pos)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu:\n");
-	PRINT_RCU_DATA(rcu_data, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh:\n");
-	PRINT_RCU_DATA(rcu_bh_data, buf, ebuf);
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
+	typedef struct rcu_data *(*get_data_func)(int);
+
+	if (*pos == 0)	/* just in case, cpu 0 is not the first */
+		*pos = first_cpu(cpu_possible_map);
+	else
+		*pos = next_cpu_nr(*pos - 1, cpu_possible_map);
+	if ((*pos) < nr_cpu_ids)
+		return ((get_data_func)m->private)(*pos);
+	return NULL;
 }
 
-static int print_one_rcu_ctrlblk(struct rcu_ctrlblk *rcp, char *buf, char *ebuf)
+static void *c_next(struct seq_file *m, void *v, loff_t *pos)
 {
-	int cnt = 0;
-
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "cur=%ld  completed=%ld  "
-			"pending=%ld  s=%d\n\t",
-			rcp->cur, rcp->completed,
-			rcp->pending, rcp->signaled);
-	cnt += cpulist_scnprintf(&buf[cnt], ebuf - &buf[cnt], rcp->cpumask);
-	cnt += snprintf(&buf[cnt], ebuf - &buf[cnt], "\n");
-	return cnt;
+	(*pos)++;
+	return c_start(m, pos);
 }
 
-static ssize_t rcucb_read(struct file *filp, char __user *buffer,
-				size_t count, loff_t *ppos)
+static void c_stop(struct seq_file *m, void *v)
 {
-	ssize_t bcount;
-	char *buf = rcuclassic_trace_buf;
-	char *ebuf = &rcuclassic_trace_buf[RCUCLASSIC_TRACE_BUF_SIZE];
-
-	mutex_lock(&rcuclassic_trace_mutex);
-	buf += snprintf(buf, ebuf - buf, "rcu: ");
-	buf += print_one_rcu_ctrlblk(&rcu_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "rcu_bh: ");
-	buf += print_one_rcu_ctrlblk(&rcu_bh_ctrlblk, buf, ebuf);
-	buf += snprintf(buf, ebuf - buf, "online: ");
-	buf += cpulist_scnprintf(buf, ebuf - buf, cpu_online_map);
-	buf += snprintf(buf, ebuf - buf, "\n");
-	bcount = simple_read_from_buffer(buffer, count, ppos,
-			rcuclassic_trace_buf, strlen(rcuclassic_trace_buf));
-	mutex_unlock(&rcuclassic_trace_mutex);
-	return bcount;
 }
 
-static struct file_operations rcudata_fops = {
-	.owner = THIS_MODULE,
-	.read = rcudata_read,
+const struct seq_operations rcu_data_seq_op = {
+	.start	= c_start,
+	.next	= c_next,
+	.stop	= c_stop,
+	.show	= show_rcu_data,
 };
 
+static int rcu_data_open(struct inode *inode, struct file *file)
+{
+	int ret = seq_open(file, &rcu_data_seq_op);
+	if (ret)
+		return ret;
+	((struct seq_file *)file->private_data)->private = inode->i_private;
+	return 0;
+}
+
+static const struct file_operations rcu_data_fops = {
+	.owner		= THIS_MODULE,
+	.open		= rcu_data_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= seq_release,
+};
+
+static void print_one_rcu_ctrlblk(struct seq_file *m, struct rcu_ctrlblk *rcp)
+{
+	seq_printf(m, "cur=%ld  completed=%ld   pending=%ld  s=%d\n\t",
+			rcp->cur, rcp->completed, rcp->pending, rcp->signaled);
+	seq_cpumask(m, &rcp->cpumask);
+	seq_puts(m, "\n");
+}
+
+static int show_rcucb(struct seq_file *m, void *unused)
+{
+	seq_puts(m, "rcu: ");
+	print_one_rcu_ctrlblk(m, &rcu_ctrlblk);
+	seq_puts(m, "rcu_bh: ");
+	print_one_rcu_ctrlblk(m, &rcu_bh_ctrlblk);
+	seq_puts(m, "online: ");
+	seq_cpumask(m, &cpu_online_map);
+	seq_puts(m, "\n");
+	return 0;
+}
+
+static int rcucb_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, show_rcucb, NULL);
+}
+
 static struct file_operations rcucb_fops = {
-	.owner = THIS_MODULE,
-	.read = rcucb_read,
+	.owner		= THIS_MODULE,
+	.open		= rcucb_open,
+	.read		= seq_read,
+	.llseek		= seq_lseek,
+	.release	= single_release,
 };
 
-static struct dentry *rcudir, *datadir, *cbdir;
-static int rcuclassic_debugfs_init(void)
+static struct dentry *rcudir, *rcu_bh_data_file, *rcu_data_file, *rcucb_file;
+
+static int __init rcuclassic_trace_init(void)
 {
 	rcudir = debugfs_create_dir("rcu", NULL);
 	if (!rcudir)
 		goto out;
-	datadir = debugfs_create_file("rcudata", 0444, rcudir,
-				      NULL, &rcudata_fops);
-	if (!datadir)
-		goto free_out;
-	cbdir = debugfs_create_file("rcucb", 0444, rcudir, NULL, &rcucb_fops);
-	if (!cbdir)
-		goto free_out;
+
+	rcu_bh_data_file = debugfs_create_file("rcu_bh_data", 0444, rcudir,
+			get_rcu_data_bh, &rcu_data_fops);
+	if (!rcu_bh_data_file)
+		goto out_rcudir;
+
+	rcu_data_file = debugfs_create_file("rcu_data", 0444, rcudir,
+			get_rcu_data, &rcu_data_fops);
+	if (!rcu_data_file)
+		goto out_rcudata_bh_file;
+
+	rcucb_file = debugfs_create_file("rcucb", 0444, rcudir,
+			NULL, &rcucb_fops);
+	if (!rcucb_file)
+		goto out_rcudata_file;
 	return 0;
-free_out:
-	if (datadir)
-		debugfs_remove(datadir);
+
+out_rcudata_file:
+	debugfs_remove(rcu_data_file);
+out_rcudata_bh_file:
+	debugfs_remove(rcu_bh_data_file);
+out_rcudir:
 	debugfs_remove(rcudir);
 out:
 	return 1;
 }
 
-static int __init rcuclassic_trace_init(void)
-{
-	int ret;
-
-	rcuclassic_trace_buf = kmalloc(RCUCLASSIC_TRACE_BUF_SIZE, GFP_KERNEL);
-	if (!rcuclassic_trace_buf)
-		return 1;
-	ret = rcuclassic_debugfs_init();
-	if (ret)
-		kfree(rcuclassic_trace_buf);
-	return ret;
-}
-
 static void __exit rcuclassic_trace_cleanup(void)
 {
-	debugfs_remove(datadir);
-	debugfs_remove(cbdir);
+	debugfs_remove(rcucb_file);
+	debugfs_remove(rcu_data_file);
+	debugfs_remove(rcu_bh_data_file);
 	debugfs_remove(rcudir);
-	kfree(rcuclassic_trace_buf);
 }
 
-
 module_init(rcuclassic_trace_init);
 module_exit(rcuclassic_trace_cleanup);
+
+MODULE_AUTHOR("Paul E. McKenney");
+MODULE_DESCRIPTION("Read-Copy Update tracing for classic implementation");
+MODULE_LICENSE("GPL");

Paul E. McKenney

2008-10-29 01:16 UTC #32 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 13 lines · Paul E. McKenney

Quoted 12 lines · Paul E. McKenney
Quoted 7 lines · Paul E. McKenney
Quoted 3 lines · Lai Jiangshan
trivial ported it to seq_file.
seq_file are very good for the output buffer.
Thank you for putting this together!!! Looks good at first glance -- I will test it out.
So it does seem to operate correctly. I combined it with my patch and applied against 2.6.27 for ease of testing.

Quoted 7 lines

Quoted 3 lines
One question -- why the multi-line format? This would be a bit awkward on a 128-CPU system, let alone on a 4,096-CPU system. Or am I missing some trick here?
To clarify, by "missing some trick", I am wondering if there is some command that works in blocks of lines. After all, /proc/cpuinfo produces the same sort of output that your patch does. ;-)

Ported to 2.6.27 to ease testing, and fixed up the formatting a bit. I remember quickly scanning through one-line-per-CPU data to find problems with rcutree.c, but the expanded names are quite nice -- I had to brutally abbreviate to fit each CPU on a single line. And I agree that seqfile does work nicely for this.

I am strongly tempted to suggest CSV format output with headers to allow the data to be pulled into gnumeric or oocalc -- this would make handling large numbers of CPUs much easier. (Quickly donning the asbestos suit with titanium pinstripes...)

Thanx, Paul

---

 include/linux/rcuclassic.h |    4 
 kernel/Kconfig.preempt     |    1 
 kernel/Makefile            |    2 
 kernel/rcuclassic.c        |    5 -
 kernel/rcuclassic_trace.c  |  198 +++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 207 insertions(+), 3 deletions(-)

include/linux/rcuclassic.h +4 -0

index 4ab8436..735f35a 100644
@@ -54,6 +54,9 @@ struct rcu_ctrlblk {
 				 /* for current batch to proceed.        */
 } ____cacheline_internodealigned_in_smp;
 
+extern struct rcu_ctrlblk rcu_ctrlblk;
+extern struct rcu_ctrlblk rcu_bh_ctrlblk;
+
 /* Is batch a before batch b ? */
 static inline int rcu_batch_before(long a, long b)
 {

@@ -76,6 +79,7 @@ struct rcu_data {
 	long		quiescbatch;     /* Batch # for grace period */
 	int		passed_quiesc;	 /* User-mode/idle loop etc. */
 	int		qs_pending;	 /* core waits for quiesc state */
+	bool		beenonline;	 /* CPU online at least once */
 
 	/* 2) batch handling */
 	long  	       	batch;           /* Batch # for current RCU batch */

kernel/Kconfig.preempt +0 -1

index 9fdba03..ba32338 100644
@@ -68,7 +68,6 @@ config PREEMPT_RCU
 
 config RCU_TRACE
 	bool "Enable tracing for RCU - currently stats in debugfs"
-	depends on PREEMPT_RCU
 	select DEBUG_FS
 	default y
 	help

kernel/Makefile +2 -0

index 4e1d7df..e0bfce7 100644
@@ -77,6 +77,8 @@ obj-$(CONFIG_CLASSIC_RCU) += rcuclassic.o
 obj-$(CONFIG_PREEMPT_RCU) += rcupreempt.o
 ifeq ($(CONFIG_PREEMPT_RCU),y)
 obj-$(CONFIG_RCU_TRACE) += rcupreempt_trace.o
+else
+obj-$(CONFIG_RCU_TRACE) += rcuclassic_trace.o
 endif
 obj-$(CONFIG_RELAY) += relay.o
 obj-$(CONFIG_SYSCTL) += utsname_sysctl.o

kernel/rcuclassic.c +3 -2

index aad93cd..06472fc 100644
@@ -57,13 +57,13 @@ EXPORT_SYMBOL_GPL(rcu_lock_map);
 
 
 /* Definition for rcupdate control block. */
-static struct rcu_ctrlblk rcu_ctrlblk = {
+struct rcu_ctrlblk rcu_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_ctrlblk.lock),
 	.cpumask = CPU_MASK_NONE,
 };
-static struct rcu_ctrlblk rcu_bh_ctrlblk = {
+struct rcu_ctrlblk rcu_bh_ctrlblk = {
 	.cur = -300,
 	.completed = -300,
 	.lock = __SPIN_LOCK_UNLOCKED(&rcu_bh_ctrlblk.lock),

@@ -564,6 +564,7 @@ static void rcu_init_percpu_data(int cpu, struct rcu_ctrlblk *rcp,
 	rdp->donetail = &rdp->donelist;
 	rdp->quiescbatch = rcp->completed;
 	rdp->qs_pending = 0;
+	rdp->beenonline = 1;
 	rdp->cpu = cpu;
 	rdp->blimit = blimit;
 }

kernel/rcuclassic_trace.c new file +198 -0

198 lines not on this page · raw message

Lai Jiangshan

2008-10-29 01:35 UTC #33 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 6 lines · Paul E. McKenney

Ported to 2.6.27 to ease testing, and fixed up the formatting a bit. I remember quickly scanning through one-line-per-CPU data to find problems with rcutree.c, but the expanded names are quite nice -- I had to brutally abbreviate to fit each CPU on a single line. And I agree that seqfile does work nicely for this.

Quoted 8 lines

I am strongly tempted to suggest CSV format output with headers to allow the data to be pulled into gnumeric or oocalc -- this would make handling large numbers of CPUs much easier. (Quickly donning the asbestos suit with titanium pinstripes...)
Thanx, Paul

Hi, Paul,
My patch is like an example, you do not need keep the
codes that I have wrote. you can rewrite all of it. these files are only accessed by RCU guys, not users. and some file in /proc is very simple but easy to be read: /proc/stat, /proc/loadavg.

Thanx, Lai.

Paul E. McKenney

2008-10-31 02:44 UTC #34 lore raw

Re: [PATCH] v3 rudimentary tracing for Classic RCU

Quoted 13 lines · Lai Jiangshan

Quoted 10 lines · Paul E. McKenney
Ported to 2.6.27 to ease testing, and fixed up the formatting a bit. I remember quickly scanning through one-line-per-CPU data to find problems with rcutree.c, but the expanded names are quite nice -- I had to brutally abbreviate to fit each CPU on a single line. And I agree that seqfile does work nicely for this.
I am strongly tempted to suggest CSV format output with headers to allow the data to be pulled into gnumeric or oocalc -- this would make handling large numbers of CPUs much easier. (Quickly donning the asbestos suit with titanium pinstripes...)

Quoted 5 lines

Hi, Paul,
My patch is like an example, you do not need keep the
codes that I have wrote. you can rewrite all of it. these files are only accessed by RCU guys, not users. and some file in /proc is very simple but easy to be read: /proc/stat, /proc/loadavg.

Hello, Jiangshan,

Good point -- I do very much appreciate the seqfile tutorial!!!

Thanx, Paul

Paul E. McKenney

2008-10-09 01:33 UTC #35 lore raw

Re: RCU hang on cpu re-hotplug with 2.6.27rc8

Quoted 40 lines · Paul E. McKenney

Quoted 30 lines · Andi Kleen
Quoted 7 lines · Paul E. McKenney
Thank you! Hmmm, classic RCU, worked just fine in 2.6.27-rc7 with Thomas's patch. I was doing random onlines and offlines in a loop, with about 3 seconds between each operation continuously for more than ten hours, both x86 and Power. So could you please try 2.6.27-rc7 with Thomas's patch as follows?
http://www.rdrop.com/users/paulmck/patches/2.6.27-rc7-tglx-timer-1.patch
Same effect. Hung on the first try
bash D 00000000ffff25c1 0 4755 4742
ffff88027b127bf8 0000000000000086 ffff88027b127c18 0000000000000296 ffff88027c80b330 ffff8804be488b90 ffff88027c80b578 0000000300000296 ffff88027b127c18 ffffffff808cbd18 ffff88002805d600 ffff88027d182098
Call Trace:
 [<ffffffff805c318d>] schedule_timeout+0x22/0xb4
 [<ffffffff8020a029>] ? __switch_to+0x320/0x330
 [<ffffffff8025fa65>] ? cpupri_set+0xc5/0xd8
 [<ffffffff805c2fe7>] wait_for_common+0xcd/0x131
 [<ffffffff8022d297>] ? default_wake_function+0x0/0xf
 [<ffffffff805c30d5>] wait_for_completion+0x18/0x1a
 [<ffffffff8024374b>] synchronize_rcu+0x35/0x3c
 [<ffffffff802437ca>] ? wakeme_after_rcu+0x0/0x12
 [<ffffffff8022e435>] partition_sched_domains+0x9b/0x1dd
 [<ffffffff8022d2c3>] ? wake_up_process+0x10/0x12
 [<ffffffff8022e5a5>] update_sched_domains+0x2e/0x35
 [<ffffffff805c6bb2>] notifier_call_chain+0x33/0x5b
 [<ffffffff80248a29>] __raw_notifier_call_chain+0x9/0xb
 [<ffffffff80248a3a>] raw_notifier_call_chain+0xf/0x11
Quoted 8 lines
 [<ffffffff805c06e6>] _cpu_up+0xd3/0x10c
 [<ffffffff805c0776>] cpu_up+0x57/0x67
 [<ffffffff805a4ab7>] store_online+0x4d/0x75
 [<ffffffff803e5d0b>] sysdev_store+0x1b/0x1d
 [<ffffffff802cc49c>] sysfs_write_file+0xe0/0x11c
 [<ffffffff8028ad1d>] vfs_write+0xae/0x137
 [<ffffffff8028b1c6>] sys_write+0x47/0x6f
 [<ffffffff8020b36b>] system_call_fastpath+0x16/0x1b

Quoted 5 lines

Thus far, as usual, I cannot reproduce, either on x86 or Power. You are running on hyperthreaded machines? If so, what happens if you disable CONFIG_SCHED_SMT and CONFIG_SCHED_MC?
You are running on a 16-CPU x86-64 box?

The attached patch (similar to one in -tip, but set up for mainline and tweaked to make stall-checking on by default) should get you a stack trace of any CPUs holding up RCU grace periods for more than about three seconds.

On the off-chance that this helps.

Thanx, Paul