From e59494f441c834ca7aaa0e6fa6678ddbd3d72743 Mon Sep 17 00:00:00 2001 From: Steven Rostedt Date: Wed, 16 Jul 2008 00:13:45 -0400 Subject: [PATCH 1/5] 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(-) 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); } From 1e01cb0c6ff7e9ddb6547551794c6aa82785a7cb Mon Sep 17 00:00:00 2001 From: Steven Rostedt Date: Tue, 15 Jul 2008 09:53:37 -0400 Subject: [PATCH 2/5] 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(-) 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 */ From 1986b0cb1671ea39178b4e2b00461109728fc935 Mon Sep 17 00:00:00 2001 From: Ingo Molnar Date: Thu, 24 Jul 2008 08:10:02 +0200 Subject: [PATCH 3/5] 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(-) 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; } From dcf309974555d17019c6a8e1a425238f17990b71 Mon Sep 17 00:00:00 2001 From: Steven Rostedt Date: Fri, 25 Jul 2008 18:00:42 -0400 Subject: [PATCH 4/5] ftrace: disable tracing on acpi idle calls The acpi idle waits calls local_irq_save and then uses mwait to go into idle. The tracer gets reenabled at local_irq_save but does not detect that the idle allows for wake ups. This patch adds code to disable the tracing when acpi puts the CPU to idle. Signed-off-by: Steven Rostedt Cc: Peter Zijlstra Signed-off-by: Ingo Molnar --- drivers/acpi/processor_idle.c | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/drivers/acpi/processor_idle.c b/drivers/acpi/processor_idle.c index d592dbb1d12a..b7f2963693a7 100644 --- a/drivers/acpi/processor_idle.c +++ b/drivers/acpi/processor_idle.c @@ -272,6 +272,8 @@ static atomic_t c3_cpu_count; /* Common C-state entry for C2, C3, .. */ static void acpi_cstate_enter(struct acpi_processor_cx *cstate) { + /* Don't trace irqs off for idle */ + stop_critical_timings(); if (cstate->entry_method == ACPI_CSTATE_FFH) { /* Call into architectural FFH based C-state */ acpi_processor_ffh_cstate_enter(cstate); @@ -284,6 +286,7 @@ static void acpi_cstate_enter(struct acpi_processor_cx *cstate) gets asserted in time to freeze execution properly. */ unused = inl(acpi_gbl_FADT.xpm_timer_block.address); } + start_critical_timings(); } #endif /* !CONFIG_CPU_IDLE */ @@ -1418,6 +1421,8 @@ static inline void acpi_idle_update_bm_rld(struct acpi_processor *pr, */ static inline void acpi_idle_do_entry(struct acpi_processor_cx *cx) { + /* Don't trace irqs off for idle */ + stop_critical_timings(); if (cx->entry_method == ACPI_CSTATE_FFH) { /* Call into architectural FFH based C-state */ acpi_processor_ffh_cstate_enter(cx); @@ -1432,6 +1437,7 @@ static inline void acpi_idle_do_entry(struct acpi_processor_cx *cx) gets asserted in time to freeze execution properly. */ unused = inl(acpi_gbl_FADT.xpm_timer_block.address); } + start_critical_timings(); } /** From 1fe371044b21b226b96a9dd959e971b50b28c78e Mon Sep 17 00:00:00 2001 From: Ingo Molnar Date: Sat, 26 Jul 2008 15:09:47 +0200 Subject: [PATCH 5/5] 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(+) 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