From e59494f441c834ca7aaa0e6fa6678ddbd3d72743 Mon Sep 17 00:00:00 2001 From: Steven Rostedt Date: Wed, 16 Jul 2008 00:13:45 -0400 Subject: ftrace: fix 4d3702b6 (post-v2.6.26): WARNING: at kernel/lockdep.c:2731 check_flags (ftrace) On Wed, 16 Jul 2008, Vegard Nossum wrote: > When booting 4d3702b6, I got this huge thing: > > Testing tracer wakeup: <4>------------[ cut here ]------------ > WARNING: at kernel/lockdep.c:2731 check_flags+0x123/0x160() > Modules linked in: > Pid: 1, comm: swapper Not tainted 2.6.26-crashing-02127-g4d3702b6 #30 > [] warn_on_slowpath+0x59/0xb0 > [] ? ftrace_call+0x5/0x8 > [] ? native_read_tsc+0x0/0x20 > [] ? sub_preempt_count+0x12/0xf0 > [] ? trace_hardirqs_off+0xb/0x10 > [] ? __lock_acquire+0x2cc/0x1120 > [] ? trace_hardirqs_off+0xb/0x10 > [] ? mcount_call+0x5/0xa > [] check_flags+0x123/0x160 > [] lock_acquire+0x51/0xd0 > [] ? ftrace_call+0x5/0x8 > [] _spin_lock_irqsave+0x5f/0xa0 > [] ? ftrace_record_ip+0xf5/0x220 > [] ? debug_locks_off+0x3/0x50 > [] ftrace_record_ip+0xf5/0x220 > [] mcount_call+0x5/0xa > [] ? debug_locks_off+0x8/0x50 > [] check_flags+0xf7/0x160 > [] lock_acquire+0x51/0xd0 > [] ? ftrace_call+0x5/0x8 > [] _spin_lock_irqsave+0x5f/0xa0 > [] ? wakeup_tracer_call+0x6d/0xf0 > [] ? _local_bh_enable+0x62/0xb0 > [] ? sub_preempt_count+0xd/0xf0 > [] wakeup_tracer_call+0x6d/0xf0 > [] ? __do_softirq+0xf4/0x110 > [] ? wakeup_tracer_call+0x91/0xf0 > [] ftrace_call+0x5/0x8 > [] ? __do_softirq+0xf4/0x110 > [] ? sub_preempt_count+0x12/0xf0 > [] _local_bh_enable+0x62/0xb0 > [] __do_softirq+0xf4/0x110 > [] do_softirq+0xad/0xb0 > [] irq_exit+0xa5/0xb0 > [] smp_apic_timer_interrupt+0x66/0xa0 > [] ? trace_hardirqs_off_thunk+0xc/0x10 > [] apic_timer_interrupt+0x2d/0x34 > [] ? find_usage_backwards+0xb/0xf0 > [] ? _spin_unlock_irqrestore+0x69/0x80 > [] tg_shares_up+0x132/0x1d0 > [] walk_tg_tree+0x62/0xa0 > [] ? tg_shares_up+0x0/0x1d0 > [] ? tg_nop+0x0/0x10 > [] update_shares+0x5d/0x80 > [] try_to_wake_up+0x6f/0x280 > [] ? __ftrace_modify_code+0x0/0xc0 > [] ? __ftrace_modify_code+0x0/0xc0 > [] wake_up_process+0x14/0x20 > [] kthread_create+0x66/0xb0 > [] ? do_stop+0x0/0x200 > [] ? __stop_machine_run+0x30/0xb0 > [] __stop_machine_run+0x50/0xb0 > [] ? do_stop+0x0/0x200 > [] ? __ftrace_modify_code+0x0/0xc0 > [] ? mutex_unlock+0xd/0x10 > [] stop_machine_run+0x2c/0x60 > [] unregister_ftrace_function+0x103/0x180 > [] stop_wakeup_tracer+0x17/0x60 > [] wakeup_tracer_ctrl_update+0xf/0x30 > [] trace_selftest_startup_wakeup+0xb5/0x130 > [] ? trace_wakeup_test_thread+0x0/0x70 > [] register_tracer+0x135/0x1b0 > [] init_wakeup_tracer+0xd/0xf > [] kernel_init+0x1a9/0x2ce > [] ? _spin_unlock_irq+0x3b/0x60 > [] ? trace_hardirqs_on_thunk+0xc/0x10 > [] ? init_wakeup_tracer+0x0/0xf > [] ? trace_hardirqs_on_caller+0x126/0x180 > [] ? trace_hardirqs_on_thunk+0xc/0x10 > [] ? restore_nocheck_notrace+0x0/0xe > [] ? kernel_init+0x0/0x2ce > [] ? kernel_init+0x0/0x2ce > [] kernel_thread_helper+0x7/0x10 > ======================= > ---[ end trace a7919e7f17c0a725 ]--- > irq event stamp: 579530 > hardirqs last enabled at (579528): [] trace_hardirqs_on+0xb/0x10 > hardirqs last disabled at (579529): [] trace_hardirqs_off+0xb/0x10 > softirqs last enabled at (579530): [] __do_softirq+0xf4/0x110 > softirqs last disabled at (579517): [] do_softirq+0xad/0xb0 > irq event stamp: 579530 > hardirqs last enabled at (579528): [] trace_hardirqs_on+0xb/0x10 > hardirqs last disabled at (579529): [] trace_hardirqs_off+0xb/0x10 > softirqs last enabled at (579530): [] __do_softirq+0xf4/0x110 > softirqs last disabled at (579517): [] do_softirq+0xad/0xb0 > PASSED > > Incidentally, the kernel also hung while I was typing in this report. Things get weird between lockdep and ftrace because ftrace can be called within lockdep internal code (via the mcount pointer) and lockdep can be called with ftrace (via spin_locks). Signed-off-by: Steven Rostedt Tested-by: Vegard Nossum Signed-off-by: Ingo Molnar --- kernel/trace/trace_sched_wakeup.c | 27 ++++++++++++++++----------- 1 file changed, 16 insertions(+), 11 deletions(-) (limited to 'kernel') diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c index 3c8d61df4474..e303ccb62cdf 100644 --- a/kernel/trace/trace_sched_wakeup.c +++ b/kernel/trace/trace_sched_wakeup.c @@ -26,7 +26,8 @@ static struct task_struct *wakeup_task; static int wakeup_cpu; static unsigned wakeup_prio = -1; -static DEFINE_SPINLOCK(wakeup_lock); +static raw_spinlock_t wakeup_lock = + (raw_spinlock_t)__RAW_SPIN_LOCK_UNLOCKED; static void __wakeup_reset(struct trace_array *tr); @@ -56,7 +57,8 @@ wakeup_tracer_call(unsigned long ip, unsigned long parent_ip) if (unlikely(disabled != 1)) goto out; - spin_lock_irqsave(&wakeup_lock, flags); + local_irq_save(flags); + __raw_spin_lock(&wakeup_lock); if (unlikely(!wakeup_task)) goto unlock; @@ -71,7 +73,8 @@ wakeup_tracer_call(unsigned long ip, unsigned long parent_ip) trace_function(tr, data, ip, parent_ip, flags); unlock: - spin_unlock_irqrestore(&wakeup_lock, flags); + __raw_spin_unlock(&wakeup_lock); + local_irq_restore(flags); out: atomic_dec(&data->disabled); @@ -145,7 +148,8 @@ wakeup_sched_switch(void *private, void *rq, struct task_struct *prev, if (likely(disabled != 1)) goto out; - spin_lock_irqsave(&wakeup_lock, flags); + local_irq_save(flags); + __raw_spin_lock(&wakeup_lock); /* We could race with grabbing wakeup_lock */ if (unlikely(!tracer_enabled || next != wakeup_task)) @@ -174,7 +178,8 @@ wakeup_sched_switch(void *private, void *rq, struct task_struct *prev, out_unlock: __wakeup_reset(tr); - spin_unlock_irqrestore(&wakeup_lock, flags); + __raw_spin_unlock(&wakeup_lock); + local_irq_restore(flags); out: atomic_dec(&tr->data[cpu]->disabled); } @@ -209,8 +214,6 @@ static void __wakeup_reset(struct trace_array *tr) struct trace_array_cpu *data; int cpu; - assert_spin_locked(&wakeup_lock); - for_each_possible_cpu(cpu) { data = tr->data[cpu]; tracing_reset(data); @@ -229,9 +232,11 @@ static void wakeup_reset(struct trace_array *tr) { unsigned long flags; - spin_lock_irqsave(&wakeup_lock, flags); + local_irq_save(flags); + __raw_spin_lock(&wakeup_lock); __wakeup_reset(tr); - spin_unlock_irqrestore(&wakeup_lock, flags); + __raw_spin_unlock(&wakeup_lock); + local_irq_restore(flags); } static void @@ -252,7 +257,7 @@ wakeup_check_start(struct trace_array *tr, struct task_struct *p, goto out; /* interrupts should be off from try_to_wake_up */ - spin_lock(&wakeup_lock); + __raw_spin_lock(&wakeup_lock); /* check for races. */ if (!tracer_enabled || p->prio >= wakeup_prio) @@ -274,7 +279,7 @@ wakeup_check_start(struct trace_array *tr, struct task_struct *p, CALLER_ADDR1, CALLER_ADDR2, flags); out_locked: - spin_unlock(&wakeup_lock); + __raw_spin_unlock(&wakeup_lock); out: atomic_dec(&tr->data[cpu]->disabled); } -- cgit v1.2.3 From 1e01cb0c6ff7e9ddb6547551794c6aa82785a7cb Mon Sep 17 00:00:00 2001 From: Steven Rostedt Date: Tue, 15 Jul 2008 09:53:37 -0400 Subject: ftrace: only trace preempt off with preempt tracer When PREEMPT_TRACER and IRQSOFF_TRACER are both configured and irqsoff tracer is running, the preempt_off sections might also be traced. Thanks to Andrew Morton for pointing out my mistake of spin_lock disabling interrupts while he was reviewing ftrace.txt. Seems that my example I used actually hit this bug. Signed-off-by: Steven Rostedt Cc: Linus Torvalds Cc: Andrew Morton Cc: Peter Zijlstra Signed-off-by: Ingo Molnar --- kernel/trace/trace_irqsoff.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) (limited to 'kernel') diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index 421d6fe3650e..b1e4a89b08eb 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -337,12 +337,14 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller); #ifdef CONFIG_PREEMPT_TRACER void trace_preempt_on(unsigned long a0, unsigned long a1) { - stop_critical_timing(a0, a1); + if (preempt_trace()) + stop_critical_timing(a0, a1); } void trace_preempt_off(unsigned long a0, unsigned long a1) { - start_critical_timing(a0, a1); + if (preempt_trace()) + start_critical_timing(a0, a1); } #endif /* CONFIG_PREEMPT_TRACER */ -- cgit v1.2.3 From 1986b0cb1671ea39178b4e2b00461109728fc935 Mon Sep 17 00:00:00 2001 From: Ingo Molnar Date: Thu, 24 Jul 2008 08:10:02 +0200 Subject: ftrace: remove latency-tracer leftover remove the :vim=ft=help tag from trace files. I used them years ago to syntax-highlight traces and forgot about this hack. Signed-off-by: Ingo Molnar --- kernel/trace/trace.c | 3 --- 1 file changed, 3 deletions(-) (limited to 'kernel') diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 868e121c8e38..fc20e09a6cb1 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -1203,9 +1203,6 @@ static void *s_next(struct seq_file *m, void *v, loff_t *pos) iter->pos = *pos; - if (last_ent && !ent) - seq_puts(m, "\n\nvim:ft=help\n"); - return ent; } -- cgit v1.2.3 From 1fe371044b21b226b96a9dd959e971b50b28c78e Mon Sep 17 00:00:00 2001 From: Ingo Molnar Date: Sat, 26 Jul 2008 15:09:47 +0200 Subject: ftrace: fix modular build fix: ERROR: "start_critical_timings" [drivers/acpi/processor.ko] undefined! ERROR: "stop_critical_timings" [drivers/acpi/processor.ko] undefined! Signed-off-by: Ingo Molnar --- kernel/trace/trace_irqsoff.c | 2 ++ 1 file changed, 2 insertions(+) (limited to 'kernel') diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index b1e4a89b08eb..ece6cfb649fa 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -253,12 +253,14 @@ void start_critical_timings(void) if (preempt_trace() || irq_trace()) start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); } +EXPORT_SYMBOL_GPL(start_critical_timings); void stop_critical_timings(void) { if (preempt_trace() || irq_trace()) stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); } +EXPORT_SYMBOL_GPL(stop_critical_timings); #ifdef CONFIG_IRQSOFF_TRACER #ifdef CONFIG_PROVE_LOCKING -- cgit v1.2.3