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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.