From 63c4db78e80407976e47bccaa2a4d8251b5a10bc Mon Sep 17 00:00:00 2001 From: Paul E. McKenney Date: Fri, 9 Aug 2013 12:19:29 -0700 Subject: rcu: Add tracing to rcu_gp_kthread() This commit adds tracing to the rcu_gp_kthread() function in order to help trace down hangs potentially involving this kthread. Reported-by: Clark Williams Reported-by: Carsten Emde Signed-off-by: Paul E. McKenney --- include/trace/events/rcu.h | 28 +++++++++++++++++++--------- 1 file changed, 19 insertions(+), 9 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h index ee2376cfaab3..60077e12093c 100644 --- a/include/trace/events/rcu.h +++ b/include/trace/events/rcu.h @@ -39,15 +39,25 @@ TRACE_EVENT(rcu_utilization, #if defined(CONFIG_TREE_RCU) || defined(CONFIG_TREE_PREEMPT_RCU) /* - * Tracepoint for grace-period events: starting and ending a grace - * period ("start" and "end", respectively), a CPU noting the start - * of a new grace period or the end of an old grace period ("cpustart" - * and "cpuend", respectively), a CPU passing through a quiescent - * state ("cpuqs"), a CPU coming online or going offline ("cpuonl" - * and "cpuofl", respectively), a CPU being kicked for being too - * long in dyntick-idle mode ("kick"), a CPU accelerating its new - * callbacks to RCU_NEXT_READY_TAIL ("AccReadyCB"), and a CPU - * accelerating its new callbacks to RCU_WAIT_TAIL ("AccWaitCB"). + * Tracepoint for grace-period events. Takes a string identifying the + * RCU flavor, the grace-period number, and a string identifying the + * grace-period-related event as follows: + * + * "AccReadyCB": CPU acclerates new callbacks to RCU_NEXT_READY_TAIL. + * "AccWaitCB": CPU accelerates new callbacks to RCU_WAIT_TAIL. + * "start": Start a grace period. + * "cpustart": CPU first notices a grace-period start. + * "cpuqs": CPU passes through a quiescent state. + * "cpuonl": CPU comes online. + * "cpuofl": CPU goes offline. + * "reqwait": GP kthread sleeps waiting for grace-period request. + * "reqwaitsig": GP kthread awakened by signal from reqwait state. + * "fqswait": GP kthread waiting until time to force quiescent states. + * "fqsstart": GP kthread starts forcing quiescent states. + * "fqsend": GP kthread done forcing quiescent states. + * "fqswaitsig": GP kthread awakened by signal from fqswait state. + * "end": End a grace period. + * "cpuend": CPU first notices a grace-period end. */ TRACE_EVENT(rcu_grace_period, -- cgit v1.2.3 From bb311eccbdab974639263060b8452bf304af0b0c Mon Sep 17 00:00:00 2001 From: Paul E. McKenney Date: Fri, 9 Aug 2013 16:02:09 -0700 Subject: rcu: Add tracing of normal (non-NOCB) grace-period requests This commit adds tracing to the normal grace-period request points. These are rcu_gp_cleanup(), which checks for the need for another grace period at the end of the previous grace period, and rcu_start_gp_advanced(), which restarts RCU's state machine after an idle period. These trace events are intended to help track down bugs where RCU remains idle despite there being work for it to do. Reported-by: Clark Williams Signed-off-by: Paul E. McKenney --- include/trace/events/rcu.h | 1 + kernel/rcutree.c | 8 +++++++- 2 files changed, 8 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h index 60077e12093c..98466c618ebc 100644 --- a/include/trace/events/rcu.h +++ b/include/trace/events/rcu.h @@ -45,6 +45,7 @@ TRACE_EVENT(rcu_utilization, * * "AccReadyCB": CPU acclerates new callbacks to RCU_NEXT_READY_TAIL. * "AccWaitCB": CPU accelerates new callbacks to RCU_WAIT_TAIL. + * "newreq": Request a new grace period. * "start": Start a grace period. * "cpustart": CPU first notices a grace-period start. * "cpuqs": CPU passes through a quiescent state. diff --git a/kernel/rcutree.c b/kernel/rcutree.c index 78d371526667..54dd6d03dbb5 100644 --- a/kernel/rcutree.c +++ b/kernel/rcutree.c @@ -1459,8 +1459,12 @@ static void rcu_gp_cleanup(struct rcu_state *rsp) rsp->fqs_state = RCU_GP_IDLE; rdp = this_cpu_ptr(rsp->rda); rcu_advance_cbs(rsp, rnp, rdp); /* Reduce false positives below. */ - if (cpu_needs_another_gp(rsp, rdp)) + if (cpu_needs_another_gp(rsp, rdp)) { rsp->gp_flags = 1; + trace_rcu_grace_period(rsp->name, + ACCESS_ONCE(rsp->gpnum), + TPS("newreq")); + } raw_spin_unlock_irq(&rnp->lock); } @@ -1584,6 +1588,8 @@ rcu_start_gp_advanced(struct rcu_state *rsp, struct rcu_node *rnp, return; } rsp->gp_flags = RCU_GP_FLAG_INIT; + trace_rcu_grace_period(rsp->name, ACCESS_ONCE(rsp->gpnum), + TPS("newreq")); /* * We can't do wakeups while holding the rnp->lock, as that -- cgit v1.2.3 From 9261dd0da6c6432f08670719069449c6efe4f7a9 Mon Sep 17 00:00:00 2001 From: Paul E. McKenney Date: Wed, 14 Aug 2013 16:24:26 -0700 Subject: rcu: Add tracing for rcuo no-CBs CPU wakeup handshake Lost wakeups from call_rcu() to the rcuo kthreads can result in hangs that are difficult to diagnose. This commit therefore adds tracing to help pin down the cause of these hangs. Reported-by: Clark Williams Reported-by: Carsten Emde Signed-off-by: Paul E. McKenney [ paulmck: Add const per kbuild test robot's advice. ] --- include/trace/events/rcu.h | 37 +++++++++++++++++++++++++++++++++++++ kernel/rcutree_plugin.h | 14 +++++++++++++- 2 files changed, 50 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h index 98466c618ebc..4301cd9e3ee5 100644 --- a/include/trace/events/rcu.h +++ b/include/trace/events/rcu.h @@ -171,6 +171,42 @@ TRACE_EVENT(rcu_grace_period_init, __entry->grplo, __entry->grphi, __entry->qsmask) ); +/* + * Tracepoint for RCU no-CBs CPU callback handoffs. This event is intended + * to assist debugging of these handoffs. + * + * The first argument is the name of the RCU flavor, and the second is + * the number of the offloaded CPU are extracted. The third and final + * argument is a string as follows: + * + * "WakeEmpty": Wake rcuo kthread, first CB to empty list. + * "WakeOvf": Wake rcuo kthread, CB list is huge. + * "WakeNot": Don't wake rcuo kthread. + * "WakeNotPoll": Don't wake rcuo kthread because it is polling. + * "WokeEmpty": rcuo kthread woke to find empty list. + * "WokeNonEmpty": rcuo kthread woke to find non-empty list. + */ +TRACE_EVENT(rcu_nocb_wake, + + TP_PROTO(const char *rcuname, int cpu, const char *reason), + + TP_ARGS(rcuname, cpu, reason), + + TP_STRUCT__entry( + __field(const char *, rcuname) + __field(int, cpu) + __field(const char *, reason) + ), + + TP_fast_assign( + __entry->rcuname = rcuname; + __entry->cpu = cpu; + __entry->reason = reason; + ), + + TP_printk("%s %d %s", __entry->rcuname, __entry->cpu, __entry->reason) +); + /* * Tracepoint for tasks blocking within preemptible-RCU read-side * critical sections. Track the type of RCU (which one day might @@ -667,6 +703,7 @@ TRACE_EVENT(rcu_barrier, #define trace_rcu_future_grace_period(rcuname, gpnum, completed, c, \ level, grplo, grphi, event) \ do { } while (0) +#define trace_rcu_nocb_wake(rcuname, cpu, reason) do { } while (0) #define trace_rcu_preempt_task(rcuname, pid, gpnum) do { } while (0) #define trace_rcu_unlock_preempted_task(rcuname, gpnum, pid) do { } while (0) #define trace_rcu_quiescent_state_report(rcuname, gpnum, mask, qsmask, level, \ diff --git a/kernel/rcutree_plugin.h b/kernel/rcutree_plugin.h index 130c97b027f2..f4ed24b18e77 100644 --- a/kernel/rcutree_plugin.h +++ b/kernel/rcutree_plugin.h @@ -2108,15 +2108,22 @@ static void __call_rcu_nocb_enqueue(struct rcu_data *rdp, /* If we are not being polled and there is a kthread, awaken it ... */ t = ACCESS_ONCE(rdp->nocb_kthread); - if (rcu_nocb_poll | !t) + if (rcu_nocb_poll | !t) { + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("WakeNotPoll")); return; + } len = atomic_long_read(&rdp->nocb_q_count); if (old_rhpp == &rdp->nocb_head) { wake_up(&rdp->nocb_wq); /* ... only if queue was empty ... */ rdp->qlen_last_fqs_check = 0; + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, TPS("WakeEmpty")); } else if (len > rdp->qlen_last_fqs_check + qhimark) { wake_up_process(t); /* ... or if many callbacks queued. */ rdp->qlen_last_fqs_check = LONG_MAX / 2; + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, TPS("WakeOvf")); + } else { + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, TPS("WakeNot")); } return; } @@ -2233,10 +2240,15 @@ static int rcu_nocb_kthread(void *arg) wait_event_interruptible(rdp->nocb_wq, rdp->nocb_head); list = ACCESS_ONCE(rdp->nocb_head); if (!list) { + if (!rcu_nocb_poll) + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("WokeEmpty")); schedule_timeout_interruptible(1); flush_signals(current); continue; } + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("WokeNonEmpty")); /* * Extract queued callbacks, update counts, and wait -- cgit v1.2.3 From 69a79bb12a81024d718e73c52e886907a3777b34 Mon Sep 17 00:00:00 2001 From: Paul E. McKenney Date: Thu, 15 Aug 2013 13:23:23 -0700 Subject: rcu: Track rcu_nocb_kthread()'s sleeping and awakening This commit adds event traces to track all of rcu_nocb_kthread()'s blocking and awakening. Signed-off-by: Paul E. McKenney --- include/trace/events/rcu.h | 4 ++++ kernel/rcutree_plugin.h | 15 ++++++++++++++- 2 files changed, 18 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h index 4301cd9e3ee5..a087d82ed431 100644 --- a/include/trace/events/rcu.h +++ b/include/trace/events/rcu.h @@ -183,8 +183,12 @@ TRACE_EVENT(rcu_grace_period_init, * "WakeOvf": Wake rcuo kthread, CB list is huge. * "WakeNot": Don't wake rcuo kthread. * "WakeNotPoll": Don't wake rcuo kthread because it is polling. + * "Poll": Start of new polling cycle for rcu_nocb_poll. + * "Sleep": Sleep waiting for CBs for !rcu_nocb_poll. * "WokeEmpty": rcuo kthread woke to find empty list. * "WokeNonEmpty": rcuo kthread woke to find non-empty list. + * "WaitQueue": Enqueue partially done, timed wait for it to complete. + * "WokeQueue": Partial enqueue now complete. */ TRACE_EVENT(rcu_nocb_wake, diff --git a/kernel/rcutree_plugin.h b/kernel/rcutree_plugin.h index 24b01b69be92..21205b185340 100644 --- a/kernel/rcutree_plugin.h +++ b/kernel/rcutree_plugin.h @@ -2230,6 +2230,7 @@ static void rcu_nocb_wait_gp(struct rcu_data *rdp) static int rcu_nocb_kthread(void *arg) { int c, cl; + bool firsttime = 1; struct rcu_head *list; struct rcu_head *next; struct rcu_head **tail; @@ -2238,8 +2239,15 @@ static int rcu_nocb_kthread(void *arg) /* Each pass through this loop invokes one batch of callbacks */ for (;;) { /* If not polling, wait for next batch of callbacks. */ - if (!rcu_nocb_poll) + if (!rcu_nocb_poll) { + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("Sleep")); wait_event_interruptible(rdp->nocb_wq, rdp->nocb_head); + } else if (firsttime) { + firsttime = 0; + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("Poll")); + } list = ACCESS_ONCE(rdp->nocb_head); if (!list) { if (!rcu_nocb_poll) @@ -2249,6 +2257,7 @@ static int rcu_nocb_kthread(void *arg) flush_signals(current); continue; } + firsttime = 1; trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, TPS("WokeNonEmpty")); @@ -2271,7 +2280,11 @@ static int rcu_nocb_kthread(void *arg) next = list->next; /* Wait for enqueuing to complete, if needed. */ while (next == NULL && &list->next != tail) { + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("WaitQueue")); schedule_timeout_interruptible(1); + trace_rcu_nocb_wake(rdp->rsp->name, rdp->cpu, + TPS("WokeQueue")); next = list->next; } debug_rcu_head_unqueue(list); -- cgit v1.2.3 From 15f5191b6acbbb38029b06284e8fd20275e7cfe8 Mon Sep 17 00:00:00 2001 From: Paul E. McKenney Date: Sun, 18 Aug 2013 11:59:25 -0700 Subject: rcu: Avoid sparse warnings in rcu_nocb_wake trace event The event-tracing macros do not like bool tracing arguments, so this commit makes them be of type char. This change has the knock-on effect of making it illegal to pass a pointer into one of these arguments, so also change rcutiny's first call to trace_rcu_batch_end() to convert from pointer to boolean, prefixing with "!!". Reported-by: kbuild test robot Signed-off-by: Paul E. McKenney --- include/trace/events/rcu.h | 10 +++++----- kernel/rcutiny.c | 2 +- 2 files changed, 6 insertions(+), 6 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h index a087d82ed431..aca382266411 100644 --- a/include/trace/events/rcu.h +++ b/include/trace/events/rcu.h @@ -591,17 +591,17 @@ TRACE_EVENT(rcu_invoke_kfree_callback, TRACE_EVENT(rcu_batch_end, TP_PROTO(const char *rcuname, int callbacks_invoked, - bool cb, bool nr, bool iit, bool risk), + char cb, char nr, char iit, char risk), TP_ARGS(rcuname, callbacks_invoked, cb, nr, iit, risk), TP_STRUCT__entry( __field(const char *, rcuname) __field(int, callbacks_invoked) - __field(bool, cb) - __field(bool, nr) - __field(bool, iit) - __field(bool, risk) + __field(char, cb) + __field(char, nr) + __field(char, iit) + __field(char, risk) ), TP_fast_assign( diff --git a/kernel/rcutiny.c b/kernel/rcutiny.c index 9ed6075dc562..80b6e273f1c5 100644 --- a/kernel/rcutiny.c +++ b/kernel/rcutiny.c @@ -273,7 +273,7 @@ static void __rcu_process_callbacks(struct rcu_ctrlblk *rcp) if (&rcp->rcucblist == rcp->donetail) { RCU_TRACE(trace_rcu_batch_start(rcp->name, 0, 0, -1)); RCU_TRACE(trace_rcu_batch_end(rcp->name, 0, - ACCESS_ONCE(rcp->rcucblist), + !!ACCESS_ONCE(rcp->rcucblist), need_resched(), is_idle_task(current), false)); -- cgit v1.2.3