From: Ingo Molnar <mingo@elte.hu>
To: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: Steven Rostedt <rostedt@goodmis.org>,
Frederic Weisbecker <fweisbec@gmail.com>,
LKML <linux-kernel@vger.kernel.org>,
Thomas Gleixner <tglx@linutronix.de>,
Peter Zijlstra <peterz@infradead.org>
Subject: Re: [PATCH 0/5] [GIT PULL] updates for tip/tracing/ftrace
Date: Sun, 22 Mar 2009 15:24:09 +0100 [thread overview]
Message-ID: <20090322142409.GA3279@elte.hu> (raw)
In-Reply-To: <20090321210154.GD7148@linux.vnet.ibm.com>
* Paul E. McKenney <paulmck@linux.vnet.ibm.com> wrote:
> > for one of the hung boxes in the past i waited 24 hours but it
> > never unwedged itself. The box that hung today is still hanging
> > and the RCU stall detector is still busy printing out those
> > backtraces.
>
> And on the last trace you emailed, the first and the last stall
> warning are identical according to "diff". In fact, they are all
> identical. That is a bit unusual, one would normally expect to see
> slight differences in the stack based on the scheduling clock
> interrupt hitting the "longer than average loop" in different
> places each time.
>
> That would indicate either a very tight loop or a loop that has
> interrupts enabled only in one spot.
With the help of Frederic's watchdog patch, i now have an ftrace
dump of the hang:
[<ffffffff8028f999>] ? test_ti_thread_flag+0x9/0x14
[<ffffffff80a04dce>] ? _spin_unlock+0x4b/0x63
[<ffffffff8036f186>] ? proc_register+0x1b5/0x1c0
[<ffffffff8029da92>] ? register_irq_proc+0xc4/0xf5
[<ffffffff8128f140>] ? early_idt_handler+0x0/0x6a
[<ffffffff8128f700>] ? do_initcalls+0x1e/0x30
[<ffffffff8128f72f>] ? do_basic_setup+0x1d/0x1f
[<ffffffff8128fc04>] ? kernel_init+0x69/0xce
[<ffffffff8020da1a>] ? child_rip+0xa/0x20
[<ffffffff8020d3ad>] ? restore_args+0x0/0x30
[<ffffffff8128fb9b>] ? kernel_init+0x0/0xce
[<ffffffff8020da10>] ? child_rip+0x0/0x20
BUG: Function graph tracer hang!
Dumping ftrace buffer:
---------------------------------
0) | ack_apic_edge() {
0) 0.000 us | }
0) 0.000 us | irq_complete_move();
0) | move_native_irq() {
0) 0.000 us | }
0) 0.000 us | }
0) | ack_APIC_irq() {
0) 0.000 us | native_apic_mem_write();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) | _spin_unlock() {
0) 0.000 us | }
0) 0.000 us | preempt_schedule();
0) 0.000 us | }
0) | handle_IRQ_event() {
0) 0.000 us | }
0) | timer_interrupt() {
0) | tick_do_periodic_broadcast() {
0) 0.000 us | }
0) | cpumask_and() {
0) 0.000 us | }
0) 0.000 us | }
0) | tick_do_broadcast() {
0) 0.000 us | }
0) | tick_handle_periodic() {
0) | write_seqlock() {
0) 0.000 us | }
0) 0.000 us | }
0) | do_timer() {
1) ==========> |
1) | smp_apic_timer_interrupt() {
1) | apic_write() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) | exit_idle() {
1) | mce_idle_callback() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | test_ti_thread_flag();
1) 0.000 us | }
1) 0.000 us | }
1) | irq_enter() {
1) 0.000 us | }
1) | tick_check_idle() {
1) 0.000 us | }
1) | tick_nohz_stop_idle() {
1) | ktime_get_ts() {
1) | clocksource_read() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | set_normalized_timespec();
1) 0.000 us | }
1) | timespec_to_ktime() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) | ktime_get() {
1) | getnstimeofday() {
1) 0.000 us | jiffies_read();
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | set_normalized_timespec();
1) 0.000 us | }
1) | timespec_to_ktime() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | tick_nohz_update_jiffies();
1) 0.000 us | }
1) 0.000 us | }
1) | local_apic_timer_interrupt() {
1) | tick_periodic() {
1) | account_process_tick() {
1) 0.000 us | }
1) 0.000 us | }
1) | run_local_timers() {
1) 0.000 us | }
1) | raise_softirq() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) | rcu_pending() {
1) 0.000 us | check_cpu_stall();
0) | update_wall_time() {
0) 0.000 us | jiffies_read();
0) 0.000 us | }
0) 0.000 us | clocksource_adjust();
0) 0.000 us | update_xtime_cache();
0) | change_clocksource() {
0) 0.000 us | _spin_lock_irqsave();
0) | _spin_unlock_irqrestore() {
0) 0.000 us | }
0) 0.000 us | preempt_schedule();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) | update_vsyscall() {
0) 0.000 us | _spin_lock();
0) 0.000 us | }
0) | write_sequnlock() {
0) 0.000 us | test_ti_thread_flag();
0) 0.000 us | preempt_schedule();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | calc_load();
0) 0.000 us | }
0) ! 1000.000 us | }
0) | write_sequnlock() {
0) 0.000 us | test_ti_thread_flag();
0) 0.000 us | preempt_schedule();
0) 0.000 us | }
0) 0.000 us | }
0) | update_process_times() {
0) | account_system_time() {
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) | run_local_timers() {
0) 0.000 us | }
0) | raise_softirq() {
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) | rcu_pending() {
0) 0.000 us | check_cpu_stall();
0) 0.000 us | }
0) 0.000 us | }
0) | rcu_check_callbacks() {
0) 0.000 us | }
1) ! 1000.000 us | }
1) | __rcu_pending() {
1) 0.000 us | }
1) 0.000 us | }
1) ! 1000.000 us | }
1) 0.000 us | printk_tick();
1) | scheduler_tick() {
1) | ktime_get_ts() {
1) | clocksource_read() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | set_normalized_timespec();
1) 0.000 us | }
1) | timespec_to_ktime() {
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | _spin_lock();
1) 0.000 us | update_rq_clock();
1) 0.000 us | update_cpu_load();
1) 0.000 us | task_tick_idle();
1) | perf_counter_task_tick() {
1) | perf_swcounter_event() {
1) 0.000 us | perf_swcounter_ctx_event();
1) 0.000 us | perf_swcounter_ctx_event();
1) 0.000 us | test_ti_thread_flag();
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) 0.000 us | }
1) ! 1000.000 us | }
1) ! 1000.000 us | }
1) ! 1000.000 us | }
1) ! 1000.000 us | }
1) ! 1000.000 us | }
1) <========== |
1) ! 1000.000 us | }
1) ! 1000.000 us | }
---------------------------------
FAILED!
initcall init_graph_trace+0x0/0x12 returned -1 after 324385776 usecs
initcall init_graph_trace+0x0/0x12 returned with error code -1
calling init_bts_trace+0x0/0x12 @ 1
Unfortunately it's rather short, due to the recent shrinking of the
default ftrace buffer sizes.
Which makes me wonder ... maybe there's a connection?
Also, the time deltas look very weird. Either 0 or 1 msec. That's
characteristic of a sched_clock() that has fallen back to a jiffies
clocksource.
Ingo
next prev parent reply other threads:[~2009-03-22 14:24 UTC|newest]
Thread overview: 48+ messages / expand[flat|nested] mbox.gz Atom feed top
2009-03-18 3:14 [PATCH 0/5] [GIT PULL] updates for tip/tracing/ftrace Steven Rostedt
2009-03-18 3:14 ` [PATCH 1/5] ring-buffer: add api to allow a tracer to change clock source Steven Rostedt
2009-03-18 3:14 ` [PATCH 2/5] tracing: add global-clock option to provide cross CPU clock to traces Steven Rostedt
2009-03-18 3:14 ` [PATCH 3/5] tracing: optimization of branch tracer Steven Rostedt
2009-03-18 3:14 ` [PATCH 4/5] tracing: make sched_switch stop/start light weight Steven Rostedt
2009-03-18 3:14 ` [PATCH 5/5] tracing: make power tracer start/stop methods lighter weight Steven Rostedt
2009-03-18 5:59 ` [PATCH 0/5] [GIT PULL] updates for tip/tracing/ftrace Ingo Molnar
2009-03-18 7:39 ` Ingo Molnar
2009-03-19 7:33 ` Ingo Molnar
2009-03-19 17:21 ` Steven Rostedt
2009-03-20 17:43 ` Paul E. McKenney
2009-03-20 18:36 ` Ingo Molnar
2009-03-20 18:38 ` Ingo Molnar
2009-03-20 19:19 ` Paul E. McKenney
2009-03-20 19:27 ` Ingo Molnar
2009-03-20 19:41 ` Paul E. McKenney
2009-03-20 19:46 ` Frederic Weisbecker
2009-03-20 19:54 ` Ingo Molnar
2009-03-20 20:48 ` Frederic Weisbecker
2009-03-20 21:05 ` Steven Rostedt
2009-03-21 10:01 ` Ingo Molnar
2009-03-21 16:58 ` Ingo Molnar
2009-03-21 17:25 ` Steven Rostedt
2009-03-21 19:07 ` Paul E. McKenney
2009-03-21 20:09 ` Ingo Molnar
2009-03-21 21:01 ` Paul E. McKenney
2009-03-22 14:24 ` Ingo Molnar [this message]
2009-03-22 15:06 ` Ingo Molnar
2009-03-22 17:02 ` Ingo Molnar
2009-03-22 18:33 ` Steven Rostedt
2009-03-22 19:52 ` Ingo Molnar
2009-03-23 18:44 ` Steven Rostedt
2009-03-21 17:32 ` Frederic Weisbecker
2009-03-21 17:44 ` Steven Rostedt
2009-03-21 17:53 ` Frederic Weisbecker
2009-03-21 18:17 ` Steven Rostedt
2009-03-21 20:03 ` Frederic Weisbecker
2009-03-21 18:18 ` Ingo Molnar
2009-03-21 20:09 ` Frederic Weisbecker
2009-03-21 20:46 ` Frederic Weisbecker
2009-03-22 19:41 ` Ingo Molnar
2009-03-22 20:41 ` Ingo Molnar
2009-03-20 21:39 ` Paul E. McKenney
2009-03-20 17:05 ` Frederic Weisbecker
2009-03-20 17:57 ` Frederic Weisbecker
2009-03-20 18:22 ` Steven Rostedt
2009-03-20 18:39 ` Frederic Weisbecker
2009-03-20 18:42 ` Ingo Molnar
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20090322142409.GA3279@elte.hu \
--to=mingo@elte.hu \
--cc=fweisbec@gmail.com \
--cc=linux-kernel@vger.kernel.org \
--cc=paulmck@linux.vnet.ibm.com \
--cc=peterz@infradead.org \
--cc=rostedt@goodmis.org \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox