diff options
author | Frederic Weisbecker <fweisbec@gmail.com> | 2009-03-17 17:38:58 -0400 |
---|---|---|
committer | Ingo Molnar <mingo@elte.hu> | 2009-03-18 05:12:38 -0400 |
commit | 490362003457f8d387f6f6e73e3a7efbf56c3314 (patch) | |
tree | b2976ec33eac69243d564661fcbc52d0fd573cdb /kernel | |
parent | 327019b01e068d66dada6a8b2571180ab3674d20 (diff) |
tracing/ftrace: stop {irqs, preempt}soff tracers when tracing is stopped
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: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
LKML-Reference: <1237325938-5240-1-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Diffstat (limited to 'kernel')
-rw-r--r-- | kernel/trace/trace_selftest.c | 26 |
1 files changed, 26 insertions, 0 deletions
diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c index a2ca6f0fef9b..38856ba78a92 100644 --- a/kernel/trace/trace_selftest.c +++ b/kernel/trace/trace_selftest.c | |||
@@ -315,6 +315,14 @@ trace_selftest_startup_irqsoff(struct tracer *trace, struct trace_array *tr) | |||
315 | local_irq_disable(); | 315 | local_irq_disable(); |
316 | udelay(100); | 316 | udelay(100); |
317 | local_irq_enable(); | 317 | local_irq_enable(); |
318 | |||
319 | /* | ||
320 | * Stop the tracer to avoid a warning subsequent | ||
321 | * to buffer flipping failure because tracing_stop() | ||
322 | * disables the tr and max buffers, making flipping impossible | ||
323 | * in case of parallels max irqs off latencies. | ||
324 | */ | ||
325 | trace->stop(tr); | ||
318 | /* stop the tracing. */ | 326 | /* stop the tracing. */ |
319 | tracing_stop(); | 327 | tracing_stop(); |
320 | /* check both trace buffers */ | 328 | /* check both trace buffers */ |
@@ -369,6 +377,14 @@ trace_selftest_startup_preemptoff(struct tracer *trace, struct trace_array *tr) | |||
369 | preempt_disable(); | 377 | preempt_disable(); |
370 | udelay(100); | 378 | udelay(100); |
371 | preempt_enable(); | 379 | preempt_enable(); |
380 | |||
381 | /* | ||
382 | * Stop the tracer to avoid a warning subsequent | ||
383 | * to buffer flipping failure because tracing_stop() | ||
384 | * disables the tr and max buffers, making flipping impossible | ||
385 | * in case of parallels max preempt off latencies. | ||
386 | */ | ||
387 | trace->stop(tr); | ||
372 | /* stop the tracing. */ | 388 | /* stop the tracing. */ |
373 | tracing_stop(); | 389 | tracing_stop(); |
374 | /* check both trace buffers */ | 390 | /* check both trace buffers */ |
@@ -428,6 +444,13 @@ trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array * | |||
428 | /* reverse the order of preempt vs irqs */ | 444 | /* reverse the order of preempt vs irqs */ |
429 | local_irq_enable(); | 445 | local_irq_enable(); |
430 | 446 | ||
447 | /* | ||
448 | * Stop the tracer to avoid a warning subsequent | ||
449 | * to buffer flipping failure because tracing_stop() | ||
450 | * disables the tr and max buffers, making flipping impossible | ||
451 | * in case of parallels max irqs/preempt off latencies. | ||
452 | */ | ||
453 | trace->stop(tr); | ||
431 | /* stop the tracing. */ | 454 | /* stop the tracing. */ |
432 | tracing_stop(); | 455 | tracing_stop(); |
433 | /* check both trace buffers */ | 456 | /* check both trace buffers */ |
@@ -448,6 +471,8 @@ trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array * | |||
448 | /* do the test by disabling interrupts first this time */ | 471 | /* do the test by disabling interrupts first this time */ |
449 | tracing_max_latency = 0; | 472 | tracing_max_latency = 0; |
450 | tracing_start(); | 473 | tracing_start(); |
474 | trace->start(tr); | ||
475 | |||
451 | preempt_disable(); | 476 | preempt_disable(); |
452 | local_irq_disable(); | 477 | local_irq_disable(); |
453 | udelay(100); | 478 | udelay(100); |
@@ -455,6 +480,7 @@ trace_selftest_startup_preemptirqsoff(struct tracer *trace, struct trace_array * | |||
455 | /* reverse the order of preempt vs irqs */ | 480 | /* reverse the order of preempt vs irqs */ |
456 | local_irq_enable(); | 481 | local_irq_enable(); |
457 | 482 | ||
483 | trace->stop(tr); | ||
458 | /* stop the tracing. */ | 484 | /* stop the tracing. */ |
459 | tracing_stop(); | 485 | tracing_stop(); |
460 | /* check both trace buffers */ | 486 | /* check both trace buffers */ |