• Frederic Weisbecker's avatar
    tracing/ftrace: stop {irqs, preempt}soff tracers when tracing is stopped · 49036200
    Frederic Weisbecker authored
    Impact: fix a selftest warning
    
    In some cases, it's possible to see the following warning on irqsoff
    tracer selftest:
    
    [    4.640003] Testing tracer irqsoff: <4>------------[ cut here ]------------
    [    4.653562] WARNING: at kernel/trace/trace.c:458 update_max_tr_single+0x9a/0xc4()
    [    4.660000] Hardware name: System Product Name
    [    4.660000] Modules linked in:
    [    4.660000] Pid: 301, comm: kstop/1 Not tainted 2.6.29-rc8-tip #35837
    [    4.660000] Call Trace:
    [    4.660000]  [<4014b588>] warn_slowpath+0x79/0x8f
    [    4.660000]  [<402d6949>] ? put_dec+0x64/0x6b
    [    4.660000]  [<40162b56>] ? getnstimeofday+0x58/0xdd
    [    4.660000]  [<40162210>] ? clocksource_read+0x3/0xf
    [    4.660000]  [<4015eb44>] ? ktime_set+0x8/0x34
    [    4.660000]  [<4014101a>] ? balance_runtime+0x8/0x56
    [    4.660000]  [<405f6f11>] ? _spin_lock+0x3/0x10
    [    4.660000]  [<4011f643>] ? ftrace_call+0x5/0x8
    [    4.660000]  [<4015d0f1>] ? task_cputime_zero+0x3/0x27
    [    4.660000]  [<40190ee7>] ? cpupri_set+0x90/0xcb
    [    4.660000]  [<405f7208>] ? _spin_lock_irqsave+0x22/0x34
    [    4.660000]  [<40190f12>] ? cpupri_set+0xbb/0xcb
    [    4.660000]  [<405f7151>] ? _spin_unlock_irqrestore+0x23/0x35
    [    4.660000]  [<4018493f>] ? ring_buffer_reset_cpu+0x27/0x51
    [    4.660000]  [<405f7208>] ? _spin_lock_irqsave+0x22/0x34
    [    4.660000]  [<40184962>] ? ring_buffer_reset_cpu+0x4a/0x51
    [    4.660000]  [<405f7151>] ? _spin_unlock_irqrestore+0x23/0x35
    [    4.660000]  [<4018cc29>] ? trace_hardirqs_off+0x1a/0x1c
    [    4.660000]  [<405f7151>] ? _spin_unlock_irqrestore+0x23/0x35
    [    4.660000]  [<40184962>] ? ring_buffer_reset_cpu+0x4a/0x51
    [    4.660000]  [<401850f3>] ? cpumask_next+0x15/0x18
    [    4.660000]  [<4018a41f>] update_max_tr_single+0x9a/0xc4
    [    4.660000]  [<4014e5fe>] ? exit_notify+0x16/0xf2
    [    4.660000]  [<4018cd13>] check_critical_timing+0xcc/0x11e
    [    4.660000]  [<4014e5fe>] ? exit_notify+0x16/0xf2
    [    4.660000]  [<4014e5fe>] ? exit_notify+0x16/0xf2
    [    4.660000]  [<4018cdf1>] stop_critical_timing+0x8c/0x9f
    [    4.660000]  [<4014e5c4>] ? forget_original_parent+0xac/0xd0
    [    4.660000]  [<4018ce3a>] trace_hardirqs_on+0x1a/0x1c
    [    4.660000]  [<4014e5c4>] forget_original_parent+0xac/0xd0
    [    4.660000]  [<4014e5fe>] exit_notify+0x16/0xf2
    [    4.660000]  [<4014e8a5>] do_exit+0x1cb/0x225
    [    4.660000]  [<4015c72b>] ? kthread+0x0/0x69
    [    4.660000]  [<4011f61d>] kernel_thread_helper+0xd/0x10
    [    4.660000] ---[ end trace a7919e7f17c0a725 ]---
    [    4.660164] .. no entries found ..FAILED!
    
    During the selftest of irqsoff tracer, we do that:
    
    	/* disable interrupts for a bit */
    	local_irq_disable();
    	udelay(100);
    	local_irq_enable();
    	/* stop the tracing. */
    	tracing_stop();
    	/* check both trace buffers */
    	ret = trace_test_buffer(tr, NULL);
    
    If a callsite performs a new max delay with irqs off just after
    tracing_stop, update_max_tr_single() -> ring_buffer_swap_cpu()
    will be called with the buffers disabled by tracing_stop(), hence
    the warning, then ring_buffer_swap_cpu() return -EAGAIN and
    update_max_tr_single() complains.
    
    Fix it by also stopping the tracer before stopping the tracing globally.
    A similar situation can happen with preemptoff and preemptirqsoff tracers
    where we apply the same fix.
    Reported-by: default avatarIngo Molnar <mingo@elte.hu>
    Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
    Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
    LKML-Reference: <1237325938-5240-1-git-send-email-fweisbec@gmail.com>
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    49036200
trace_selftest.c 15 KB