Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Frederic Weisbecker <fweisbec@gmail.com>]

On Sun, Apr 19, 2009 at 03:49:28PM +0200, Frederic Weisbecker wrote:
> On Sun, Apr 19, 2009 at 02:34:32PM +0200, Frederic Weisbecker wrote:
> > On Sun, Apr 19, 2009 at 02:14:54PM +0800, Li Zefan wrote:
> > > Frederic Weisbecker wrote:
> > > > Hi,
> > > > 
> > > > Here is the v3 of the __string() field patchset.
> > > > It applies suggestions from Steven and Peter with some arrangements.
> > > > 
> > > > This time, filtering is not supported (though it is ready in a pending patch).
> > > > I wanted to provide it but it looks like filtering has been broken recently.
> > > > Once I set a usual string filter, no more traces appear, and clearing it
> > > > doesn't change anything.
> > > > 
> > > 
> > > I tried it, and triggered a WARNING, and ring buffers was
> > > disabled permanently:
> > 
> > 
> > I've also seen this warning but on another event.
> > I don't think this is related to this patchset but
> > more about the tracing recursion detection.
> > 
> > For exemple, here we are in an Irq event, which doesn't
> > use the __string() thing. For such off-case, the only change
> > is a variable declaration and a + 0 operation.
> > 
> > Another thing: I've only seen it in a selftest.
> 
> 
> Worst: I can't reproduce it anymore.
> What were you doing when you got such warning? Were you
> in a selftest, or trying a usual event?



Now I can reproduce it. It seems to happen when I set a filter,
but also on other situations:

Bisected back to:

commit 261842b7c9099f56de2eb969c8ad65402d68e00e
tracing: add same level recursion detection

It might be caused by a bug in this patch or
by real tracing recursions on some places.

Another example:

111.119821] ------------[ cut here ]------------
[  111.119829] WARNING: at kernel/trace/ring_buffer.c:1498 ring_buffer_lock_reserve+0x1b7/0x1d0()
[  111.119835] Hardware name: AMILO Li 2727                  
[  111.119839] Modules linked in:
[  111.119846] Pid: 5731, comm: Xorg Tainted: G        W  2.6.30-rc1 #69
[  111.119851] Call Trace:
[  111.119863]  [<ffffffff8025ce68>] warn_slowpath+0xd8/0x130
[  111.119873]  [<ffffffff8028a30f>] ? __lock_acquire+0x19f/0x1ae0
[  111.119882]  [<ffffffff8028a30f>] ? __lock_acquire+0x19f/0x1ae0
[  111.119891]  [<ffffffff802199b0>] ? native_sched_clock+0x20/0x70
[  111.119899]  [<ffffffff80286dee>] ? put_lock_stats+0xe/0x30
[  111.119906]  [<ffffffff80286eb8>] ? lock_release_holdtime+0xa8/0x150
[  111.119913]  [<ffffffff802c8ae7>] ring_buffer_lock_reserve+0x1b7/0x1d0
[  111.119921]  [<ffffffff802cd110>] trace_buffer_lock_reserve+0x30/0x70
[  111.119930]  [<ffffffff802ce000>] trace_current_buffer_lock_reserve+0x20/0x30
[  111.119939]  [<ffffffff802474e8>] ftrace_raw_event_sched_switch+0x58/0x100
[  111.119948]  [<ffffffff808103b7>] __schedule+0x3a7/0x4cd
[  111.119957]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.119964]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.119971]  [<ffffffff80810c08>] schedule+0x18/0x40
[  111.119977]  [<ffffffff80810e09>] preempt_schedule+0x39/0x60
[  111.119985]  [<ffffffff80813bd3>] _read_unlock+0x53/0x60
[  111.119993]  [<ffffffff807259d2>] sock_def_readable+0x72/0x80
[  111.120002]  [<ffffffff807ad5ed>] unix_stream_sendmsg+0x24d/0x3d0
[  111.120011]  [<ffffffff807219a3>] sock_aio_write+0x143/0x160
[  111.120019]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120026]  [<ffffffff80721860>] ? sock_aio_write+0x0/0x160
[  111.120033]  [<ffffffff80721860>] ? sock_aio_write+0x0/0x160
[  111.120042]  [<ffffffff8031c283>] do_sync_readv_writev+0xf3/0x140
[  111.120049]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120057]  [<ffffffff80276ff0>] ? autoremove_wake_function+0x0/0x40
[  111.120067]  [<ffffffff8045d489>] ? cap_file_permission+0x9/0x10
[  111.120074]  [<ffffffff8045c1e6>] ? security_file_permission+0x16/0x20
[  111.120082]  [<ffffffff8031cab4>] do_readv_writev+0xd4/0x1f0
[  111.120089]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120097]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120105]  [<ffffffff8031cc18>] vfs_writev+0x48/0x70
[  111.120111]  [<ffffffff8031cd65>] sys_writev+0x55/0xc0
[  111.120119]  [<ffffffff80211e32>] system_call_fastpath+0x16/0x1b
[  111.120125] ---[ end trace 15605f4e98d5ccb5 ]---


Frederic.

 
> Also, could you test the following patch. It will give us
> more informations about the tracing recursion.
> 
> You can find it on:
> 
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion
> 
> It's against tip/tracing/core
> 
> Thanks!
> 
> ---
> From d13bf59ca011b976c561f623e3189a4a5b94370e Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Sun, 19 Apr 2009 15:30:19 +0200
> Subject: [PATCH] tracing/core: Add current context on tracing recursion warning
> 
> In case of tracing recursion detection, we only get the stacktrace.
> But the current context may be very useful to debug the issue.
> 
> This patch adds the softirq/hardirq/nmi context with the warning
> using lockdep context display to have a familiar output.
> 
> [ Impact: more information in tracing recursion ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/ring_buffer.c |   13 +++++++++++++
>  1 files changed, 13 insertions(+), 0 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index b421b0e..27a6e7d 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -1493,8 +1493,21 @@ static int trace_recursive_lock(void)
>  	level = trace_irq_level();
>  
>  	if (unlikely(current->trace_recursion & (1 << level))) {
> +		static atomic_t warned;
> +
>  		/* Disable all tracing before we do anything else */
>  		tracing_off_permanent();
> +
> +		if (atomic_inc_return(&warned) == 1) {
> +			printk(KERN_WARNING "Tracing recursion: "
> +				"[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
> +				current->hardirq_context,
> +				hardirq_count() >> HARDIRQ_SHIFT,
> +				current->softirq_context,
> +				softirq_count() >> SOFTIRQ_SHIFT,
> +				in_nmi(), current->hardirqs_enabled,
> +				current->softirqs_enabled);
> +		}
>  		WARN_ON_ONCE(1);
>  		return -1;
>  	}
> -- 
> 1.6.1
> 
>