* [ltt-dev] lttctl locks up with RT Linux [not found] ` <A47866F933DF804684068A24BF04A97309116C93@gdrs-exchange.gdrs.com> @ 2010-05-11 11:59 ` Mathieu Desnoyers 2010-05-11 14:50 ` jpaul 0 siblings, 1 reply; 10+ messages in thread From: Mathieu Desnoyers @ 2010-05-11 11:59 UTC (permalink / raw) * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Hey Mathieu: > > Thanks for looking at this. I'm a bit new to debugging at this level, so > you may need to provide me a bit more info on what you need. I attempted > to use "pstack" on the lttctl and lttd tasks ... no luck as pstack also > locked up. > > I put a bit of tracing into liblttctl and discovered the lockup occurs > when a write of "traceName" (whatever traceName happens to be) occurs to > the "/mnt/debugfs/ltt/destroy_trace" file. > > I'm guessing that you would like some tracing of the ltt kernel module. > Is there something that I can turn on, or another way I could get a > stack dump of that module after lockup? I'll do a little research this > weekend on kernel debugging techniques. > > I can certainly sprinkle in some printk statements in the ltt kernel > module source. Doing provided the following info: > > - Control entered _ltt_trace_destroy (single underscore) > - Control entered del_timer_sync(<t_async_wakeup_timer) and never > returned > > Does that help, or should I continue farther down this path? Can you try the following patch to see if it fixes your problem ? lttng fix rt kernel teardown deadlock LTTng has a teardown bug on RT (deadlock): Deleting a timer (sync) while holding the traces mutex, and the handler takes the same mutex, which leads to a deadlock. Fix this by taking a RCU read lock in the timer (instead of the RT-specific fix using the mutex), and by doing synchronize_rcu() in addition to synchronize_sched() upon updates. Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> --- ltt/ltt-tracer.c | 28 ++++++++++++++++++---------- 1 file changed, 18 insertions(+), 10 deletions(-) Index: linux-2.6-lttng/ltt/ltt-tracer.c =================================================================== --- linux-2.6-lttng.orig/ltt/ltt-tracer.c 2010-05-11 07:50:46.000000000 -0400 +++ linux-2.6-lttng/ltt/ltt-tracer.c 2010-05-11 07:55:46.000000000 -0400 @@ -41,6 +41,14 @@ #include <linux/vmalloc.h> #include <asm/atomic.h> +static void synchronize_trace(void) +{ + synchronize_sched(); +#ifdef CONFIG_PREEMPT_RT + synchronize_rcu(); +#endif +} + static void async_wakeup(unsigned long data); static DEFINE_TIMER(ltt_async_wakeup_timer, async_wakeup, 0, 0); @@ -321,7 +329,7 @@ void ltt_module_unregister(enum ltt_modu ltt_filter_unregister(); ltt_run_filter_owner = NULL; /* Wait for preempt sections to finish */ - synchronize_sched(); + synchronize_trace(); break; case LTT_FUNCTION_FILTER_CONTROL: ltt_filter_control_functor = ltt_filter_control_default; @@ -429,13 +437,13 @@ static void async_wakeup(unsigned long d * PREEMPT_RT does not allow spinlocks to be taken within preempt * disable sections (spinlock taken in wake_up). However, mainline won't * allow mutex to be taken in interrupt context. Ugly. - * A proper way to do this would be to turn the timer into a - * periodically woken up thread, but it adds to the footprint. + * Take a standard RCU read lock for RT kernels, which imply that we + * also have to synchronize_rcu() upon updates. */ #ifndef CONFIG_PREEMPT_RT rcu_read_lock_sched(); #else - ltt_lock_traces(); + rcu_read_lock(); #endif list_for_each_entry_rcu(trace, <t_traces.head, list) { trace_async_wakeup(trace); @@ -443,7 +451,7 @@ static void async_wakeup(unsigned long d #ifndef CONFIG_PREEMPT_RT rcu_read_unlock_sched(); #else - ltt_unlock_traces(); + rcu_read_unlock(); #endif mod_timer(<t_async_wakeup_timer, jiffies + LTT_PERCPU_TIMER_INTERVAL); @@ -901,7 +909,7 @@ int ltt_trace_alloc(const char *trace_na set_kernel_trace_flag_all_tasks(); } list_add_rcu(&trace->list, <t_traces.head); - synchronize_sched(); + synchronize_trace(); ltt_unlock_traces(); @@ -974,7 +982,7 @@ static int _ltt_trace_destroy(struct ltt } /* Everything went fine */ list_del_rcu(&trace->list); - synchronize_sched(); + synchronize_trace(); if (list_empty(<t_traces.head)) { clear_kernel_trace_flag_all_tasks(); /* @@ -1195,7 +1203,7 @@ static int _ltt_trace_stop(struct ltt_tr trace->nr_channels); trace->active = 0; ltt_traces.num_active_traces--; - synchronize_sched(); /* Wait for each tracing to be finished */ + synchronize_trace(); /* Wait for each tracing to be finished */ } module_put(ltt_run_filter_owner); /* Everything went fine */ @@ -1327,12 +1335,12 @@ static void __exit ltt_exit(void) list_for_each_entry_rcu(trace, <t_traces.head, list) _ltt_trace_stop(trace); /* Wait for quiescent state. Readers have preemption disabled. */ - synchronize_sched(); + synchronize_trace(); /* Safe iteration is now permitted. It does not have to be RCU-safe * because no readers are left. */ list_for_each_safe(pos, n, <t_traces.head) { trace = container_of(pos, struct ltt_trace, list); - /* _ltt_trace_destroy does a synchronize_sched() */ + /* _ltt_trace_destroy does a synchronize_trace() */ _ltt_trace_destroy(trace); __ltt_trace_destroy(trace); } > > Thanks > > JP > > -----Original Message----- > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > Sent: Thursday, April 22, 2010 12:06 PM > To: John P. Paul > Cc: ltt-dev at lists.casi.polymtl.ca > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > Greetings: > > > > I'm using a a 2.6.33.2 kernel. I have LTT up and running on the plain > vanilla kernel, but "lttctl -D trace1" never returns on the RT version > of the same kernel. I've downloaded and integrated the following pieces: > > > > patch-2.6.33.2-lttng-0.211 > > ltt-control-0.84-07042010 > > lttv-0.12.31.04072010 > > > > Note that I've had to manually apply several of the patches from the > patch file. I can provide a list if desired. > > > > After the lockup, I can do an ls on the /tmp/trace directory and see > that the following files have a non-zero length (remaining files in the > trace directory have a zero length): > > > > fs_0, fs_1, kernel_0, kernel_1 > > > > I'm running on an Intel Core2 Duo system. I've built all the LTT > components into the kernel, so I do not have to load any modules at > runtime. I do execute an ltt-armall prior to issuing any "lttctl -C -w > /tmp/trace trace1" commands. > > > > When the above occurs, I usually have to hard power down the machine > as a root issued "reboot" does not reboot the machine (even after trying > to kill the running ltt processes). > > > > Any suggestions on how to get this working under the RT kernel would > be appreciated. Does LTT even function properly for RT kernels? If not, > it would be of great benefit to have it do so. Please let me know if > additional debug info would be helpful. > > I bet there is something fishy on RT with __ltt_trace_destroy(). Having > an output of where the CPU is stalled in lttng code would help. > > > > > > A couple additional notes: > > > > - LTTV docs state that it requires glib 2.4 or greater. I believe this > is incorrect due to the following dependency: > > > > $ rpm -qa glib2 > > glib2-2.12.3-4.el5_3.1 << my default glib (RHEL5.x base) > > > > state.c: In function 'copy_process_state': > > state.c:1344: error: 'GHashTableIter' undeclared (first use in this > function) > > > > I've installed glib-2.22.5 to get around the above issue. > > OK, the dependency seems to be glib 2.16 now. Will update the README > and LTTng manual accordingly. > > Thanks, > > Mathieu > > > > -- > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > > > _______________________________________________ > ltt-dev mailing list > ltt-dev at lists.casi.polymtl.ca > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev > -- Mathieu Desnoyers Operating System Efficiency R&D Consultant EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-11 11:59 ` [ltt-dev] lttctl locks up with RT Linux Mathieu Desnoyers @ 2010-05-11 14:50 ` jpaul 2010-05-11 15:11 ` Mathieu Desnoyers 0 siblings, 1 reply; 10+ messages in thread From: jpaul @ 2010-05-11 14:50 UTC (permalink / raw) Thanks Mathieu. I'm going to have to look at this a bit more. This may have fixed one problem and cause another as "lttctl -C -w /tmp/trace trace1" does not return and I'm getting a stack dump in the messages file (see below). The last msg I see from that "lttctl -C" command is "lttctl: Creating trace". The "lttctl: Forking lttd" is not displayed. JP May 11 10:05:00 ans-ebb3 kernel: P5 May 11 10:05:00 ans-ebb3 kernel: INFO: RCU detected CPU stalls: P5 (detected by 0, t=10002 jiffies) May 11 10:05:00 ans-ebb3 kernel: sending NMI to all CPUs: May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 1 May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] May 11 10:05:00 ans-ebb3 kernel: May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c062e4fa>] EFLAGS: 00000246 CPU: 1 May 11 10:05:00 ans-ebb3 kernel: EIP is at poll_idle+0x1e/0x5c May 11 10:05:00 ans-ebb3 kernel: EAX: f74bc000 EBX: 6b655cfc ECX: 6b655cfc EDX: 000001a2 May 11 10:05:00 ans-ebb3 kernel: ESI: 000001a2 EDI: 00000000 EBP: f74bcf84 ESP: f74bcf7c May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04010002 May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=f74bc000 task=f74d90c0 task.ti=f74bc000) May 11 10:05:00 ans-ebb3 kernel: Stack: May 11 10:05:00 ans-ebb3 kernel: f765b02c f765b01c f74bcf94 c062e7c9 00000001 c0877c90 f74bcfa4 c0401c0d May 11 10:05:00 ans-ebb3 kernel: <0> 00000001 00000000 f74bcfb0 c06ca177 01020800 00000000 00000000 00000000 May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000d8 May 11 10:05:00 ans-ebb3 kernel: Call Trace: May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] ? start_secondary+0x1b9/0x1be May 11 10:05:00 ans-ebb3 kernel: Code: ff ff ff 8d 65 f4 89 d8 5b 5e 5f 5d c3 55 89 e5 56 53 e8 7b 61 e2 ff 89 c3 89 d6 fb 89 e0 25 00 f0 ff ff eb 02 f3 90 f6 40 08 08 <74> f8 e8 60 61 e2 ff 29 d8 19 f2 e8 95 b6 e0 ff b9 40 42 0f 00 May 11 10:05:00 ans-ebb3 kernel: Call Trace: May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 May 11 10:05:00 ans-ebb3 kernel: Call Trace: May 11 10:05:00 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 May 11 10:05:00 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 May 11 10:05:00 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 May 11 10:05:00 ans-ebb3 kernel: [<c056355d>] ? ltt_chan_for_each_channel+0x35/0x4f May 11 10:05:00 ans-ebb3 kernel: [<c05628df>] ? ltt_chanbuf_idle_switch+0x0/0x1c May 11 10:05:00 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d May 11 10:05:00 ans-ebb3 kernel: [<c062e4fa>] ? poll_idle+0x1e/0x5c May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 0 May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] May 11 10:05:00 ans-ebb3 kernel: May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c0570ab6>] EFLAGS: 00000807 CPU: 0 May 11 10:05:00 ans-ebb3 kernel: EIP is at delay_tsc+0x0/0x8a May 11 10:05:00 ans-ebb3 kernel: EAX: 001c7b29 EBX: 00000001 ECX: 04f29000 EDX: 001c7b28 May 11 10:05:00 ans-ebb3 kernel: ESI: 00000000 EDI: c084a6c0 EBP: c0828e6c ESP: c0828e68 May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04020002 May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=c0828000 task=c08407a0 task.ti=c0828000) May 11 10:05:00 ans-ebb3 kernel: Stack: May 11 10:05:00 ans-ebb3 kernel: c0570a4f c0828e78 c0418e84 c084a740 c0828eb0 c047c35b c07c1944 00000000 May 11 10:05:00 ans-ebb3 kernel: <0> 00002712 c5805268 c084a6c0 c084a6ec 00000003 c084a740 00000083 00000000 May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 c08407a0 c0828ec0 c047c45f 00000000 00000000 c0828ed4 c0441fbd May 11 10:05:00 ans-ebb3 kernel: Call Trace: May 11 10:05:00 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] ? arch_trigger_all_cpu_backtrace+0x42/0x4f May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] ? __rcu_pending+0x258/0x309 May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] ? rcu_check_callbacks+0x53/0x114 May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] ? update_process_times+0x32/0x43 May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] ? tick_sched_timer+0x6d/0x9b May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] ? __run_hrtimer+0xeb/0x154 May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] ? hrtimer_interrupt+0xed/0x21e May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] ? smp_apic_timer_interrupt+0xb4/0x106 May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] ? apic_timer_interrupt+0x2a/0x30 May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] ? rest_init+0x80/0x82 May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] ? start_kernel+0x2fb/0x300 May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] ? i386_start_kernel+0x8c/0x91 May 11 10:05:01 ans-ebb3 kernel: Code: c0 8b 0c 8d 18 7b 87 c0 6b c0 14 ba 40 ff 8d c0 55 89 e5 69 94 0a 98 00 00 00 fa 00 00 00 f7 e2 8d 42 01 ff 15 90 84 85 c0 5d c3 <55> 89 e5 57 56 89 c6 53 83 ec 04 89 e0 25 00 f0 ff ff ff 40 14 May 11 10:05:01 ans-ebb3 kernel: Call Trace: May 11 10:05:01 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 May 11 10:05:01 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 May 11 10:05:01 ans-ebb3 kernel: Call Trace: May 11 10:05:01 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 May 11 10:05:01 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 May 11 10:05:01 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 May 11 10:05:01 ans-ebb3 kernel: [<c05645a8>] ? ltt_vtrace+0x0/0x79b May 11 10:05:02 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d May 11 10:05:02 ans-ebb3 kernel: [<c0570ab6>] ? delay_tsc+0x0/0x8a May 11 10:05:02 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 May 11 10:05:02 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f May 11 10:05:02 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 May 11 10:05:02 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 May 11 10:05:02 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 May 11 10:05:02 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b May 11 10:05:02 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b May 11 10:05:02 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 May 11 10:05:02 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e May 11 10:05:02 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 May 11 10:05:02 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 May 11 10:05:02 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 May 11 10:05:02 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c May 11 10:05:02 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf May 11 10:05:02 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 May 11 10:05:02 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 May 11 10:05:02 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 May 11 10:05:02 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 -----Original Message----- From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] Sent: Tue 5/11/2010 7:59 AM To: John P. Paul Cc: ltt-dev at lists.casi.polymtl.ca Subject: Re: [ltt-dev] lttctl locks up with RT Linux * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Hey Mathieu: > > Thanks for looking at this. I'm a bit new to debugging at this level, so > you may need to provide me a bit more info on what you need. I attempted > to use "pstack" on the lttctl and lttd tasks ... no luck as pstack also > locked up. > > I put a bit of tracing into liblttctl and discovered the lockup occurs > when a write of "traceName" (whatever traceName happens to be) occurs to > the "/mnt/debugfs/ltt/destroy_trace" file. > > I'm guessing that you would like some tracing of the ltt kernel module. > Is there something that I can turn on, or another way I could get a > stack dump of that module after lockup? I'll do a little research this > weekend on kernel debugging techniques. > > I can certainly sprinkle in some printk statements in the ltt kernel > module source. Doing provided the following info: > > - Control entered _ltt_trace_destroy (single underscore) > - Control entered del_timer_sync(<t_async_wakeup_timer) and never > returned > > Does that help, or should I continue farther down this path? Can you try the following patch to see if it fixes your problem ? lttng fix rt kernel teardown deadlock LTTng has a teardown bug on RT (deadlock): Deleting a timer (sync) while holding the traces mutex, and the handler takes the same mutex, which leads to a deadlock. Fix this by taking a RCU read lock in the timer (instead of the RT-specific fix using the mutex), and by doing synchronize_rcu() in addition to synchronize_sched() upon updates. Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> --- ltt/ltt-tracer.c | 28 ++++++++++++++++++---------- 1 file changed, 18 insertions(+), 10 deletions(-) Index: linux-2.6-lttng/ltt/ltt-tracer.c =================================================================== --- linux-2.6-lttng.orig/ltt/ltt-tracer.c 2010-05-11 07:50:46.000000000 -0400 +++ linux-2.6-lttng/ltt/ltt-tracer.c 2010-05-11 07:55:46.000000000 -0400 @@ -41,6 +41,14 @@ #include <linux/vmalloc.h> #include <asm/atomic.h> +static void synchronize_trace(void) +{ + synchronize_sched(); +#ifdef CONFIG_PREEMPT_RT + synchronize_rcu(); +#endif +} + static void async_wakeup(unsigned long data); static DEFINE_TIMER(ltt_async_wakeup_timer, async_wakeup, 0, 0); @@ -321,7 +329,7 @@ void ltt_module_unregister(enum ltt_modu ltt_filter_unregister(); ltt_run_filter_owner = NULL; /* Wait for preempt sections to finish */ - synchronize_sched(); + synchronize_trace(); break; case LTT_FUNCTION_FILTER_CONTROL: ltt_filter_control_functor = ltt_filter_control_default; @@ -429,13 +437,13 @@ static void async_wakeup(unsigned long d * PREEMPT_RT does not allow spinlocks to be taken within preempt * disable sections (spinlock taken in wake_up). However, mainline won't * allow mutex to be taken in interrupt context. Ugly. - * A proper way to do this would be to turn the timer into a - * periodically woken up thread, but it adds to the footprint. + * Take a standard RCU read lock for RT kernels, which imply that we + * also have to synchronize_rcu() upon updates. */ #ifndef CONFIG_PREEMPT_RT rcu_read_lock_sched(); #else - ltt_lock_traces(); + rcu_read_lock(); #endif list_for_each_entry_rcu(trace, <t_traces.head, list) { trace_async_wakeup(trace); @@ -443,7 +451,7 @@ static void async_wakeup(unsigned long d #ifndef CONFIG_PREEMPT_RT rcu_read_unlock_sched(); #else - ltt_unlock_traces(); + rcu_read_unlock(); #endif mod_timer(<t_async_wakeup_timer, jiffies + LTT_PERCPU_TIMER_INTERVAL); @@ -901,7 +909,7 @@ int ltt_trace_alloc(const char *trace_na set_kernel_trace_flag_all_tasks(); } list_add_rcu(&trace->list, <t_traces.head); - synchronize_sched(); + synchronize_trace(); ltt_unlock_traces(); @@ -974,7 +982,7 @@ static int _ltt_trace_destroy(struct ltt } /* Everything went fine */ list_del_rcu(&trace->list); - synchronize_sched(); + synchronize_trace(); if (list_empty(<t_traces.head)) { clear_kernel_trace_flag_all_tasks(); /* @@ -1195,7 +1203,7 @@ static int _ltt_trace_stop(struct ltt_tr trace->nr_channels); trace->active = 0; ltt_traces.num_active_traces--; - synchronize_sched(); /* Wait for each tracing to be finished */ + synchronize_trace(); /* Wait for each tracing to be finished */ } module_put(ltt_run_filter_owner); /* Everything went fine */ @@ -1327,12 +1335,12 @@ static void __exit ltt_exit(void) list_for_each_entry_rcu(trace, <t_traces.head, list) _ltt_trace_stop(trace); /* Wait for quiescent state. Readers have preemption disabled. */ - synchronize_sched(); + synchronize_trace(); /* Safe iteration is now permitted. It does not have to be RCU-safe * because no readers are left. */ list_for_each_safe(pos, n, <t_traces.head) { trace = container_of(pos, struct ltt_trace, list); - /* _ltt_trace_destroy does a synchronize_sched() */ + /* _ltt_trace_destroy does a synchronize_trace() */ _ltt_trace_destroy(trace); __ltt_trace_destroy(trace); } -- This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-11 14:50 ` jpaul @ 2010-05-11 15:11 ` Mathieu Desnoyers 2010-05-11 20:15 ` jpaul 2010-05-11 22:11 ` Paul E. McKenney 0 siblings, 2 replies; 10+ messages in thread From: Mathieu Desnoyers @ 2010-05-11 15:11 UTC (permalink / raw) * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Thanks Mathieu. I'm going to have to look at this a bit more. This may > have fixed one problem and cause another as "lttctl -C -w /tmp/trace > trace1" does not return and I'm getting a stack dump in the messages > file (see below). The last msg I see from that "lttctl -C" command is > "lttctl: Creating trace". The "lttctl: Forking lttd" is not displayed. If you disable RCU stalls detection, does it work ? [Context for Paul: it's on a -RT kernel, with the LTTng patchset] Thanks, Mathieu > > JP > > May 11 10:05:00 ans-ebb3 kernel: P5 > May 11 10:05:00 ans-ebb3 kernel: INFO: RCU detected CPU stalls: P5 (detected by 0, t=10002 jiffies) > May 11 10:05:00 ans-ebb3 kernel: sending NMI to all CPUs: > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 1 > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] > May 11 10:05:00 ans-ebb3 kernel: > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c062e4fa>] EFLAGS: 00000246 CPU: 1 > May 11 10:05:00 ans-ebb3 kernel: EIP is at poll_idle+0x1e/0x5c > May 11 10:05:00 ans-ebb3 kernel: EAX: f74bc000 EBX: 6b655cfc ECX: 6b655cfc EDX: 000001a2 > May 11 10:05:00 ans-ebb3 kernel: ESI: 000001a2 EDI: 00000000 EBP: f74bcf84 ESP: f74bcf7c > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04010002 > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=f74bc000 task=f74d90c0 task.ti=f74bc000) > May 11 10:05:00 ans-ebb3 kernel: Stack: > May 11 10:05:00 ans-ebb3 kernel: f765b02c f765b01c f74bcf94 c062e7c9 00000001 c0877c90 f74bcfa4 c0401c0d > May 11 10:05:00 ans-ebb3 kernel: <0> 00000001 00000000 f74bcfb0 c06ca177 01020800 00000000 00000000 00000000 > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000d8 > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] ? start_secondary+0x1b9/0x1be > May 11 10:05:00 ans-ebb3 kernel: Code: ff ff ff 8d 65 f4 89 d8 5b 5e 5f 5d c3 55 89 e5 56 53 e8 7b 61 e2 ff 89 c3 89 d6 fb 89 e0 25 00 f0 ff ff eb 02 f3 90 f6 40 08 08 <74> f8 e8 60 61 e2 ff 29 d8 19 f2 e8 95 b6 e0 ff b9 40 42 0f 00 > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > May 11 10:05:00 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > May 11 10:05:00 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 > May 11 10:05:00 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > May 11 10:05:00 ans-ebb3 kernel: [<c056355d>] ? ltt_chan_for_each_channel+0x35/0x4f > May 11 10:05:00 ans-ebb3 kernel: [<c05628df>] ? ltt_chanbuf_idle_switch+0x0/0x1c > May 11 10:05:00 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d > May 11 10:05:00 ans-ebb3 kernel: [<c062e4fa>] ? poll_idle+0x1e/0x5c > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 0 > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] > May 11 10:05:00 ans-ebb3 kernel: > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c0570ab6>] EFLAGS: 00000807 CPU: 0 > May 11 10:05:00 ans-ebb3 kernel: EIP is at delay_tsc+0x0/0x8a > May 11 10:05:00 ans-ebb3 kernel: EAX: 001c7b29 EBX: 00000001 ECX: 04f29000 EDX: 001c7b28 > May 11 10:05:00 ans-ebb3 kernel: ESI: 00000000 EDI: c084a6c0 EBP: c0828e6c ESP: c0828e68 > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04020002 > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=c0828000 task=c08407a0 task.ti=c0828000) > May 11 10:05:00 ans-ebb3 kernel: Stack: > May 11 10:05:00 ans-ebb3 kernel: c0570a4f c0828e78 c0418e84 c084a740 c0828eb0 c047c35b c07c1944 00000000 > May 11 10:05:00 ans-ebb3 kernel: <0> 00002712 c5805268 c084a6c0 c084a6ec 00000003 c084a740 00000083 00000000 > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 c08407a0 c0828ec0 c047c45f 00000000 00000000 c0828ed4 c0441fbd > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > May 11 10:05:00 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] ? arch_trigger_all_cpu_backtrace+0x42/0x4f > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] ? __rcu_pending+0x258/0x309 > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] ? rcu_check_callbacks+0x53/0x114 > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] ? update_process_times+0x32/0x43 > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] ? tick_sched_timer+0x6d/0x9b > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] ? __run_hrtimer+0xeb/0x154 > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] ? hrtimer_interrupt+0xed/0x21e > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] ? smp_apic_timer_interrupt+0xb4/0x106 > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] ? apic_timer_interrupt+0x2a/0x30 > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] ? rest_init+0x80/0x82 > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] ? start_kernel+0x2fb/0x300 > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] ? i386_start_kernel+0x8c/0x91 > May 11 10:05:01 ans-ebb3 kernel: Code: c0 8b 0c 8d 18 7b 87 c0 6b c0 14 ba 40 ff 8d c0 55 89 e5 69 94 0a 98 00 00 00 fa 00 00 00 f7 e2 8d 42 01 ff 15 90 84 85 c0 5d c3 <55> 89 e5 57 56 89 c6 53 83 ec 04 89 e0 25 00 f0 ff ff ff 40 14 > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > May 11 10:05:01 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 > May 11 10:05:01 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > May 11 10:05:01 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > May 11 10:05:01 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 > May 11 10:05:01 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > May 11 10:05:01 ans-ebb3 kernel: [<c05645a8>] ? ltt_vtrace+0x0/0x79b > May 11 10:05:02 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d > May 11 10:05:02 ans-ebb3 kernel: [<c0570ab6>] ? delay_tsc+0x0/0x8a > May 11 10:05:02 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > May 11 10:05:02 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f > May 11 10:05:02 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 > May 11 10:05:02 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 > May 11 10:05:02 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 > May 11 10:05:02 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b > May 11 10:05:02 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > May 11 10:05:02 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 > May 11 10:05:02 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e > May 11 10:05:02 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > May 11 10:05:02 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 > May 11 10:05:02 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 > May 11 10:05:02 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > May 11 10:05:02 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > May 11 10:05:02 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > May 11 10:05:02 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > May 11 10:05:02 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 > May 11 10:05:02 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 > > > > -----Original Message----- > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > Sent: Tue 5/11/2010 7:59 AM > To: John P. Paul > Cc: ltt-dev at lists.casi.polymtl.ca > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > Hey Mathieu: > > > > Thanks for looking at this. I'm a bit new to debugging at this level, so > > you may need to provide me a bit more info on what you need. I attempted > > to use "pstack" on the lttctl and lttd tasks ... no luck as pstack also > > locked up. > > > > I put a bit of tracing into liblttctl and discovered the lockup occurs > > when a write of "traceName" (whatever traceName happens to be) occurs to > > the "/mnt/debugfs/ltt/destroy_trace" file. > > > > I'm guessing that you would like some tracing of the ltt kernel module. > > Is there something that I can turn on, or another way I could get a > > stack dump of that module after lockup? I'll do a little research this > > weekend on kernel debugging techniques. > > > > I can certainly sprinkle in some printk statements in the ltt kernel > > module source. Doing provided the following info: > > > > - Control entered _ltt_trace_destroy (single underscore) > > - Control entered del_timer_sync(<t_async_wakeup_timer) and never > > returned > > > > Does that help, or should I continue farther down this path? > > Can you try the following patch to see if it fixes your problem ? > > > lttng fix rt kernel teardown deadlock > > LTTng has a teardown bug on RT (deadlock): > > Deleting a timer (sync) while holding the traces mutex, and the handler takes > the same mutex, which leads to a deadlock. > > Fix this by taking a RCU read lock in the timer (instead of the RT-specific fix > using the mutex), and by doing synchronize_rcu() in addition to > synchronize_sched() upon updates. > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > --- > ltt/ltt-tracer.c | 28 ++++++++++++++++++---------- > 1 file changed, 18 insertions(+), 10 deletions(-) > > Index: linux-2.6-lttng/ltt/ltt-tracer.c > =================================================================== > --- linux-2.6-lttng.orig/ltt/ltt-tracer.c 2010-05-11 07:50:46.000000000 -0400 > +++ linux-2.6-lttng/ltt/ltt-tracer.c 2010-05-11 07:55:46.000000000 -0400 > @@ -41,6 +41,14 @@ > #include <linux/vmalloc.h> > #include <asm/atomic.h> > > +static void synchronize_trace(void) > +{ > + synchronize_sched(); > +#ifdef CONFIG_PREEMPT_RT > + synchronize_rcu(); > +#endif > +} > + > static void async_wakeup(unsigned long data); > > static DEFINE_TIMER(ltt_async_wakeup_timer, async_wakeup, 0, 0); > @@ -321,7 +329,7 @@ void ltt_module_unregister(enum ltt_modu > ltt_filter_unregister(); > ltt_run_filter_owner = NULL; > /* Wait for preempt sections to finish */ > - synchronize_sched(); > + synchronize_trace(); > break; > case LTT_FUNCTION_FILTER_CONTROL: > ltt_filter_control_functor = ltt_filter_control_default; > @@ -429,13 +437,13 @@ static void async_wakeup(unsigned long d > * PREEMPT_RT does not allow spinlocks to be taken within preempt > * disable sections (spinlock taken in wake_up). However, mainline won't > * allow mutex to be taken in interrupt context. Ugly. > - * A proper way to do this would be to turn the timer into a > - * periodically woken up thread, but it adds to the footprint. > + * Take a standard RCU read lock for RT kernels, which imply that we > + * also have to synchronize_rcu() upon updates. > */ > #ifndef CONFIG_PREEMPT_RT > rcu_read_lock_sched(); > #else > - ltt_lock_traces(); > + rcu_read_lock(); > #endif > list_for_each_entry_rcu(trace, <t_traces.head, list) { > trace_async_wakeup(trace); > @@ -443,7 +451,7 @@ static void async_wakeup(unsigned long d > #ifndef CONFIG_PREEMPT_RT > rcu_read_unlock_sched(); > #else > - ltt_unlock_traces(); > + rcu_read_unlock(); > #endif > > mod_timer(<t_async_wakeup_timer, jiffies + LTT_PERCPU_TIMER_INTERVAL); > @@ -901,7 +909,7 @@ int ltt_trace_alloc(const char *trace_na > set_kernel_trace_flag_all_tasks(); > } > list_add_rcu(&trace->list, <t_traces.head); > - synchronize_sched(); > + synchronize_trace(); > > ltt_unlock_traces(); > > @@ -974,7 +982,7 @@ static int _ltt_trace_destroy(struct ltt > } > /* Everything went fine */ > list_del_rcu(&trace->list); > - synchronize_sched(); > + synchronize_trace(); > if (list_empty(<t_traces.head)) { > clear_kernel_trace_flag_all_tasks(); > /* > @@ -1195,7 +1203,7 @@ static int _ltt_trace_stop(struct ltt_tr > trace->nr_channels); > trace->active = 0; > ltt_traces.num_active_traces--; > - synchronize_sched(); /* Wait for each tracing to be finished */ > + synchronize_trace(); /* Wait for each tracing to be finished */ > } > module_put(ltt_run_filter_owner); > /* Everything went fine */ > @@ -1327,12 +1335,12 @@ static void __exit ltt_exit(void) > list_for_each_entry_rcu(trace, <t_traces.head, list) > _ltt_trace_stop(trace); > /* Wait for quiescent state. Readers have preemption disabled. */ > - synchronize_sched(); > + synchronize_trace(); > /* Safe iteration is now permitted. It does not have to be RCU-safe > * because no readers are left. */ > list_for_each_safe(pos, n, <t_traces.head) { > trace = container_of(pos, struct ltt_trace, list); > - /* _ltt_trace_destroy does a synchronize_sched() */ > + /* _ltt_trace_destroy does a synchronize_trace() */ > _ltt_trace_destroy(trace); > __ltt_trace_destroy(trace); > } > > > > -- > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > -- Mathieu Desnoyers Operating System Efficiency R&D Consultant EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-11 15:11 ` Mathieu Desnoyers @ 2010-05-11 20:15 ` jpaul 2010-05-13 18:23 ` Mathieu Desnoyers 2010-05-11 22:11 ` Paul E. McKenney 1 sibling, 1 reply; 10+ messages in thread From: jpaul @ 2010-05-11 20:15 UTC (permalink / raw) Turning off CONFIG_RCU_CPU_STALL_DETECTOR does not solve the issue with starting up "lttctl -C" ... that call never returns. I'm no longer getting the stack dumps in /var/log/messages and I still have to hard reboot the system as soft reboot doesn't work. JP -----Original Message----- From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] Sent: Tue 5/11/2010 11:11 AM To: John P. Paul Cc: ltt-dev at lists.casi.polymtl.ca; Paul E. McKenney; linux-rt-users at vger.kernel.org Subject: Re: [ltt-dev] lttctl locks up with RT Linux * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Thanks Mathieu. I'm going to have to look at this a bit more. This may > have fixed one problem and cause another as "lttctl -C -w /tmp/trace > trace1" does not return and I'm getting a stack dump in the messages > file (see below). The last msg I see from that "lttctl -C" command is > "lttctl: Creating trace". The "lttctl: Forking lttd" is not displayed. If you disable RCU stalls detection, does it work ? [Context for Paul: it's on a -RT kernel, with the LTTng patchset] Thanks, Mathieu -- This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-11 20:15 ` jpaul @ 2010-05-13 18:23 ` Mathieu Desnoyers 2010-05-14 14:33 ` jpaul 0 siblings, 1 reply; 10+ messages in thread From: Mathieu Desnoyers @ 2010-05-13 18:23 UTC (permalink / raw) Please double-check that you applied the last patch correctly. I tried building a lttng-enabled -rt tree here (x86 64 box), and it works (I can start/stop tracing and see the trace in lttv). Note that I simply discarded the conflicting instrumentation patches for this quick test. I'm pretty sure an error could have been inserted in async_wakeup() within ltt-tracer.c. Can you paste the code you have ? Unbalanced rcu read lock/unlock could be causing this. Thanks, Mathieu * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Turning off CONFIG_RCU_CPU_STALL_DETECTOR does not solve the issue with starting up "lttctl -C" ... that call never returns. I'm no longer getting the stack dumps in /var/log/messages and I still have to hard reboot the system as soft reboot doesn't work. > > JP > > > -----Original Message----- > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > Sent: Tue 5/11/2010 11:11 AM > To: John P. Paul > Cc: ltt-dev at lists.casi.polymtl.ca; Paul E. McKenney; linux-rt-users at vger.kernel.org > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > Thanks Mathieu. I'm going to have to look at this a bit more. This may > > have fixed one problem and cause another as "lttctl -C -w /tmp/trace > > trace1" does not return and I'm getting a stack dump in the messages > > file (see below). The last msg I see from that "lttctl -C" command is > > "lttctl: Creating trace". The "lttctl: Forking lttd" is not displayed. > > If you disable RCU stalls detection, does it work ? > > [Context for Paul: it's on a -RT kernel, with the LTTng patchset] > > Thanks, > > Mathieu > > -- > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > -- Mathieu Desnoyers Operating System Efficiency R&D Consultant EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-13 18:23 ` Mathieu Desnoyers @ 2010-05-14 14:33 ` jpaul 2010-05-14 14:56 ` Mathieu Desnoyers 0 siblings, 1 reply; 10+ messages in thread From: jpaul @ 2010-05-14 14:33 UTC (permalink / raw) Thanks Mathieu. This was my fault .. I couldn't apply your patch (kept getting failures on hunks 2-8 for some reason) so I hand patched the file and in doing so, transposed a rcu unlock with an rcu lock (just as you suspected). So, after correcting that, all is well and I'm able to perform tracing under 2.6.33.2 RT. Thanks Much! JP -----Original Message----- From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] Sent: Thu 5/13/2010 2:23 PM To: John P. Paul Cc: ltt-dev at lists.casi.polymtl.ca; paulmck at linux.vnet.ibm.com; linux-rt-users at vger.kernel.org Subject: Re: [ltt-dev] lttctl locks up with RT Linux Please double-check that you applied the last patch correctly. I tried building a lttng-enabled -rt tree here (x86 64 box), and it works (I can start/stop tracing and see the trace in lttv). Note that I simply discarded the conflicting instrumentation patches for this quick test. I'm pretty sure an error could have been inserted in async_wakeup() within ltt-tracer.c. Can you paste the code you have ? Unbalanced rcu read lock/unlock could be causing this. Thanks, Mathieu * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Turning off CONFIG_RCU_CPU_STALL_DETECTOR does not solve the issue with starting up "lttctl -C" ... that call never returns. I'm no longer getting the stack dumps in /var/log/messages and I still have to hard reboot the system as soft reboot doesn't work. > > JP -- This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-14 14:33 ` jpaul @ 2010-05-14 14:56 ` Mathieu Desnoyers 0 siblings, 0 replies; 10+ messages in thread From: Mathieu Desnoyers @ 2010-05-14 14:56 UTC (permalink / raw) Ah! I think I brought debugging to a whole new level here, including developer interaction in the bissection. ;) Thanks for the reports, they have been very useful to re-enable LTTng for -rt kernels, Mathieu * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > Thanks Mathieu. This was my fault .. I couldn't apply your patch > (kept getting failures on hunks 2-8 for some reason) so I hand patched > the file and in doing so, transposed a rcu unlock with an rcu lock > (just as you suspected). So, after correcting that, all is well and > I'm able to perform tracing under 2.6.33.2 RT. > > Thanks Much! > > JP > > > -----Original Message----- > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > Sent: Thu 5/13/2010 2:23 PM > To: John P. Paul > Cc: ltt-dev at lists.casi.polymtl.ca; paulmck at linux.vnet.ibm.com; linux-rt-users at vger.kernel.org > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > Please double-check that you applied the last patch correctly. I tried > building a lttng-enabled -rt tree here (x86 64 box), and it works (I can > start/stop tracing and see the trace in lttv). > > Note that I simply discarded the conflicting instrumentation patches for > this quick test. > > I'm pretty sure an error could have been inserted in async_wakeup() > within ltt-tracer.c. Can you paste the code you have ? > > Unbalanced rcu read lock/unlock could be causing this. > > Thanks, > > Mathieu > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > Turning off CONFIG_RCU_CPU_STALL_DETECTOR does not solve the issue with starting up "lttctl -C" ... that call never returns. I'm no longer getting the stack dumps in /var/log/messages and I still have to hard reboot the system as soft reboot doesn't work. > > > > JP > > -- > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > > > _______________________________________________ > ltt-dev mailing list > ltt-dev at lists.casi.polymtl.ca > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev > -- Mathieu Desnoyers Operating System Efficiency R&D Consultant EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-11 15:11 ` Mathieu Desnoyers 2010-05-11 20:15 ` jpaul @ 2010-05-11 22:11 ` Paul E. McKenney 2010-05-12 12:26 ` jpaul 1 sibling, 1 reply; 10+ messages in thread From: Paul E. McKenney @ 2010-05-11 22:11 UTC (permalink / raw) On Tue, May 11, 2010 at 11:11:20AM -0400, Mathieu Desnoyers wrote: > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > Thanks Mathieu. I'm going to have to look at this a bit more. This may > > have fixed one problem and cause another as "lttctl -C -w /tmp/trace > > trace1" does not return and I'm getting a stack dump in the messages > > file (see below). The last msg I see from that "lttctl -C" command is > > "lttctl: Creating trace". The "lttctl: Forking lttd" is not displayed. > > If you disable RCU stalls detection, does it work ? > > [Context for Paul: it's on a -RT kernel, with the LTTng patchset] Strange. It looks like everyone is idle. Or is it possible that some CPU is spinning in an NMI handler? You have six call traces -- are there six CPUs online? Thanx, Paul > Thanks, > > Mathieu > > > > > JP > > > > May 11 10:05:00 ans-ebb3 kernel: P5 > > May 11 10:05:00 ans-ebb3 kernel: INFO: RCU detected CPU stalls: P5 (detected by 0, t=10002 jiffies) > > May 11 10:05:00 ans-ebb3 kernel: sending NMI to all CPUs: > > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 1 > > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] > > May 11 10:05:00 ans-ebb3 kernel: > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c062e4fa>] EFLAGS: 00000246 CPU: 1 > > May 11 10:05:00 ans-ebb3 kernel: EIP is at poll_idle+0x1e/0x5c > > May 11 10:05:00 ans-ebb3 kernel: EAX: f74bc000 EBX: 6b655cfc ECX: 6b655cfc EDX: 000001a2 > > May 11 10:05:00 ans-ebb3 kernel: ESI: 000001a2 EDI: 00000000 EBP: f74bcf84 ESP: f74bcf7c > > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04010002 > > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=f74bc000 task=f74d90c0 task.ti=f74bc000) > > May 11 10:05:00 ans-ebb3 kernel: Stack: > > May 11 10:05:00 ans-ebb3 kernel: f765b02c f765b01c f74bcf94 c062e7c9 00000001 c0877c90 f74bcfa4 c0401c0d > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000001 00000000 f74bcfb0 c06ca177 01020800 00000000 00000000 00000000 > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000d8 > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] ? start_secondary+0x1b9/0x1be > > May 11 10:05:00 ans-ebb3 kernel: Code: ff ff ff 8d 65 f4 89 d8 5b 5e 5f 5d c3 55 89 e5 56 53 e8 7b 61 e2 ff 89 c3 89 d6 fb 89 e0 25 00 f0 ff ff eb 02 f3 90 f6 40 08 08 <74> f8 e8 60 61 e2 ff 29 d8 19 f2 e8 95 b6 e0 ff b9 40 42 0f 00 > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > > May 11 10:05:00 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 > > May 11 10:05:00 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > > May 11 10:05:00 ans-ebb3 kernel: [<c056355d>] ? ltt_chan_for_each_channel+0x35/0x4f > > May 11 10:05:00 ans-ebb3 kernel: [<c05628df>] ? ltt_chanbuf_idle_switch+0x0/0x1c > > May 11 10:05:00 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d > > May 11 10:05:00 ans-ebb3 kernel: [<c062e4fa>] ? poll_idle+0x1e/0x5c > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be > > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 0 > > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] > > May 11 10:05:00 ans-ebb3 kernel: > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c0570ab6>] EFLAGS: 00000807 CPU: 0 > > May 11 10:05:00 ans-ebb3 kernel: EIP is at delay_tsc+0x0/0x8a > > May 11 10:05:00 ans-ebb3 kernel: EAX: 001c7b29 EBX: 00000001 ECX: 04f29000 EDX: 001c7b28 > > May 11 10:05:00 ans-ebb3 kernel: ESI: 00000000 EDI: c084a6c0 EBP: c0828e6c ESP: c0828e68 > > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04020002 > > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=c0828000 task=c08407a0 task.ti=c0828000) > > May 11 10:05:00 ans-ebb3 kernel: Stack: > > May 11 10:05:00 ans-ebb3 kernel: c0570a4f c0828e78 c0418e84 c084a740 c0828eb0 c047c35b c07c1944 00000000 > > May 11 10:05:00 ans-ebb3 kernel: <0> 00002712 c5805268 c084a6c0 c084a6ec 00000003 c084a740 00000083 00000000 > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 c08407a0 c0828ec0 c047c45f 00000000 00000000 c0828ed4 c0441fbd > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] ? arch_trigger_all_cpu_backtrace+0x42/0x4f > > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] ? __rcu_pending+0x258/0x309 > > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] ? rcu_check_callbacks+0x53/0x114 > > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] ? update_process_times+0x32/0x43 > > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] ? tick_sched_timer+0x6d/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] ? __run_hrtimer+0xeb/0x154 > > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] ? hrtimer_interrupt+0xed/0x21e > > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] ? smp_apic_timer_interrupt+0xb4/0x106 > > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] ? apic_timer_interrupt+0x2a/0x30 > > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] ? rest_init+0x80/0x82 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] ? start_kernel+0x2fb/0x300 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] ? i386_start_kernel+0x8c/0x91 > > May 11 10:05:01 ans-ebb3 kernel: Code: c0 8b 0c 8d 18 7b 87 c0 6b c0 14 ba 40 ff 8d c0 55 89 e5 69 94 0a 98 00 00 00 fa 00 00 00 f7 e2 8d 42 01 ff 15 90 84 85 c0 5d c3 <55> 89 e5 57 56 89 c6 53 83 ec 04 89 e0 25 00 f0 ff ff ff 40 14 > > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > > May 11 10:05:01 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f > > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 > > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 > > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 > > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 > > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e > > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 > > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 > > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 > > May 11 10:05:01 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 > > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > > May 11 10:05:01 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > > May 11 10:05:01 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 > > May 11 10:05:01 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > > May 11 10:05:01 ans-ebb3 kernel: [<c05645a8>] ? ltt_vtrace+0x0/0x79b > > May 11 10:05:02 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d > > May 11 10:05:02 ans-ebb3 kernel: [<c0570ab6>] ? delay_tsc+0x0/0x8a > > May 11 10:05:02 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > > May 11 10:05:02 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f > > May 11 10:05:02 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 > > May 11 10:05:02 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 > > May 11 10:05:02 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 > > May 11 10:05:02 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b > > May 11 10:05:02 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > > May 11 10:05:02 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 > > May 11 10:05:02 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e > > May 11 10:05:02 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > > May 11 10:05:02 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 > > May 11 10:05:02 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 > > May 11 10:05:02 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > May 11 10:05:02 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:02 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:02 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > > May 11 10:05:02 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 > > May 11 10:05:02 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 > > > > > > > > -----Original Message----- > > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > > Sent: Tue 5/11/2010 7:59 AM > > To: John P. Paul > > Cc: ltt-dev at lists.casi.polymtl.ca > > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > > Hey Mathieu: > > > > > > Thanks for looking at this. I'm a bit new to debugging at this level, so > > > you may need to provide me a bit more info on what you need. I attempted > > > to use "pstack" on the lttctl and lttd tasks ... no luck as pstack also > > > locked up. > > > > > > I put a bit of tracing into liblttctl and discovered the lockup occurs > > > when a write of "traceName" (whatever traceName happens to be) occurs to > > > the "/mnt/debugfs/ltt/destroy_trace" file. > > > > > > I'm guessing that you would like some tracing of the ltt kernel module. > > > Is there something that I can turn on, or another way I could get a > > > stack dump of that module after lockup? I'll do a little research this > > > weekend on kernel debugging techniques. > > > > > > I can certainly sprinkle in some printk statements in the ltt kernel > > > module source. Doing provided the following info: > > > > > > - Control entered _ltt_trace_destroy (single underscore) > > > - Control entered del_timer_sync(<t_async_wakeup_timer) and never > > > returned > > > > > > Does that help, or should I continue farther down this path? > > > > Can you try the following patch to see if it fixes your problem ? > > > > > > lttng fix rt kernel teardown deadlock > > > > LTTng has a teardown bug on RT (deadlock): > > > > Deleting a timer (sync) while holding the traces mutex, and the handler takes > > the same mutex, which leads to a deadlock. > > > > Fix this by taking a RCU read lock in the timer (instead of the RT-specific fix > > using the mutex), and by doing synchronize_rcu() in addition to > > synchronize_sched() upon updates. > > > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > > --- > > ltt/ltt-tracer.c | 28 ++++++++++++++++++---------- > > 1 file changed, 18 insertions(+), 10 deletions(-) > > > > Index: linux-2.6-lttng/ltt/ltt-tracer.c > > =================================================================== > > --- linux-2.6-lttng.orig/ltt/ltt-tracer.c 2010-05-11 07:50:46.000000000 -0400 > > +++ linux-2.6-lttng/ltt/ltt-tracer.c 2010-05-11 07:55:46.000000000 -0400 > > @@ -41,6 +41,14 @@ > > #include <linux/vmalloc.h> > > #include <asm/atomic.h> > > > > +static void synchronize_trace(void) > > +{ > > + synchronize_sched(); > > +#ifdef CONFIG_PREEMPT_RT > > + synchronize_rcu(); > > +#endif > > +} > > + > > static void async_wakeup(unsigned long data); > > > > static DEFINE_TIMER(ltt_async_wakeup_timer, async_wakeup, 0, 0); > > @@ -321,7 +329,7 @@ void ltt_module_unregister(enum ltt_modu > > ltt_filter_unregister(); > > ltt_run_filter_owner = NULL; > > /* Wait for preempt sections to finish */ > > - synchronize_sched(); > > + synchronize_trace(); > > break; > > case LTT_FUNCTION_FILTER_CONTROL: > > ltt_filter_control_functor = ltt_filter_control_default; > > @@ -429,13 +437,13 @@ static void async_wakeup(unsigned long d > > * PREEMPT_RT does not allow spinlocks to be taken within preempt > > * disable sections (spinlock taken in wake_up). However, mainline won't > > * allow mutex to be taken in interrupt context. Ugly. > > - * A proper way to do this would be to turn the timer into a > > - * periodically woken up thread, but it adds to the footprint. > > + * Take a standard RCU read lock for RT kernels, which imply that we > > + * also have to synchronize_rcu() upon updates. > > */ > > #ifndef CONFIG_PREEMPT_RT > > rcu_read_lock_sched(); > > #else > > - ltt_lock_traces(); > > + rcu_read_lock(); > > #endif > > list_for_each_entry_rcu(trace, <t_traces.head, list) { > > trace_async_wakeup(trace); > > @@ -443,7 +451,7 @@ static void async_wakeup(unsigned long d > > #ifndef CONFIG_PREEMPT_RT > > rcu_read_unlock_sched(); > > #else > > - ltt_unlock_traces(); > > + rcu_read_unlock(); > > #endif > > > > mod_timer(<t_async_wakeup_timer, jiffies + LTT_PERCPU_TIMER_INTERVAL); > > @@ -901,7 +909,7 @@ int ltt_trace_alloc(const char *trace_na > > set_kernel_trace_flag_all_tasks(); > > } > > list_add_rcu(&trace->list, <t_traces.head); > > - synchronize_sched(); > > + synchronize_trace(); > > > > ltt_unlock_traces(); > > > > @@ -974,7 +982,7 @@ static int _ltt_trace_destroy(struct ltt > > } > > /* Everything went fine */ > > list_del_rcu(&trace->list); > > - synchronize_sched(); > > + synchronize_trace(); > > if (list_empty(<t_traces.head)) { > > clear_kernel_trace_flag_all_tasks(); > > /* > > @@ -1195,7 +1203,7 @@ static int _ltt_trace_stop(struct ltt_tr > > trace->nr_channels); > > trace->active = 0; > > ltt_traces.num_active_traces--; > > - synchronize_sched(); /* Wait for each tracing to be finished */ > > + synchronize_trace(); /* Wait for each tracing to be finished */ > > } > > module_put(ltt_run_filter_owner); > > /* Everything went fine */ > > @@ -1327,12 +1335,12 @@ static void __exit ltt_exit(void) > > list_for_each_entry_rcu(trace, <t_traces.head, list) > > _ltt_trace_stop(trace); > > /* Wait for quiescent state. Readers have preemption disabled. */ > > - synchronize_sched(); > > + synchronize_trace(); > > /* Safe iteration is now permitted. It does not have to be RCU-safe > > * because no readers are left. */ > > list_for_each_safe(pos, n, <t_traces.head) { > > trace = container_of(pos, struct ltt_trace, list); > > - /* _ltt_trace_destroy does a synchronize_sched() */ > > + /* _ltt_trace_destroy does a synchronize_trace() */ > > _ltt_trace_destroy(trace); > > __ltt_trace_destroy(trace); > > } > > > > > > > > -- > > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > > > > -- > Mathieu Desnoyers > Operating System Efficiency R&D Consultant > EfficiOS Inc. > http://www.efficios.com ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-11 22:11 ` Paul E. McKenney @ 2010-05-12 12:26 ` jpaul 2010-05-12 23:10 ` Paul E. McKenney 0 siblings, 1 reply; 10+ messages in thread From: jpaul @ 2010-05-12 12:26 UTC (permalink / raw) Hi Paul: I'm running on a single Intel Core 2 Duo. JP -----Original Message----- From: Paul E. McKenney [mailto:paulmck@linux.vnet.ibm.com] Sent: Tuesday, May 11, 2010 6:11 PM To: Mathieu Desnoyers Cc: John P. Paul; ltt-dev at lists.casi.polymtl.ca; linux-rt-users at vger.kernel.org Subject: Re: [ltt-dev] lttctl locks up with RT Linux On Tue, May 11, 2010 at 11:11:20AM -0400, Mathieu Desnoyers wrote: > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > Thanks Mathieu. I'm going to have to look at this a bit more. This may > > have fixed one problem and cause another as "lttctl -C -w /tmp/trace > > trace1" does not return and I'm getting a stack dump in the messages > > file (see below). The last msg I see from that "lttctl -C" command is > > "lttctl: Creating trace". The "lttctl: Forking lttd" is not displayed. > > If you disable RCU stalls detection, does it work ? > > [Context for Paul: it's on a -RT kernel, with the LTTng patchset] Strange. It looks like everyone is idle. Or is it possible that some CPU is spinning in an NMI handler? You have six call traces -- are there six CPUs online? Thanx, Paul > Thanks, > > Mathieu > > > > > JP > > > > May 11 10:05:00 ans-ebb3 kernel: P5 > > May 11 10:05:00 ans-ebb3 kernel: INFO: RCU detected CPU stalls: P5 (detected by 0, t=10002 jiffies) > > May 11 10:05:00 ans-ebb3 kernel: sending NMI to all CPUs: > > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 1 > > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] > > May 11 10:05:00 ans-ebb3 kernel: > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c062e4fa>] EFLAGS: 00000246 CPU: 1 > > May 11 10:05:00 ans-ebb3 kernel: EIP is at poll_idle+0x1e/0x5c > > May 11 10:05:00 ans-ebb3 kernel: EAX: f74bc000 EBX: 6b655cfc ECX: 6b655cfc EDX: 000001a2 > > May 11 10:05:00 ans-ebb3 kernel: ESI: 000001a2 EDI: 00000000 EBP: f74bcf84 ESP: f74bcf7c > > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04010002 > > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=f74bc000 task=f74d90c0 task.ti=f74bc000) > > May 11 10:05:00 ans-ebb3 kernel: Stack: > > May 11 10:05:00 ans-ebb3 kernel: f765b02c f765b01c f74bcf94 c062e7c9 00000001 c0877c90 f74bcfa4 c0401c0d > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000001 00000000 f74bcfb0 c06ca177 01020800 00000000 00000000 00000000 > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000d8 > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] ? start_secondary+0x1b9/0x1be > > May 11 10:05:00 ans-ebb3 kernel: Code: ff ff ff 8d 65 f4 89 d8 5b 5e 5f 5d c3 55 89 e5 56 53 e8 7b 61 e2 ff 89 c3 89 d6 fb 89 e0 25 00 f0 ff ff eb 02 f3 90 f6 40 08 08 <74> f8 e8 60 61 e2 ff 29 d8 19 f2 e8 95 b6 e0 ff b9 40 42 0f 00 > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > > May 11 10:05:00 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 > > May 11 10:05:00 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > > May 11 10:05:00 ans-ebb3 kernel: [<c056355d>] ? ltt_chan_for_each_channel+0x35/0x4f > > May 11 10:05:00 ans-ebb3 kernel: [<c05628df>] ? ltt_chanbuf_idle_switch+0x0/0x1c > > May 11 10:05:00 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d > > May 11 10:05:00 ans-ebb3 kernel: [<c062e4fa>] ? poll_idle+0x1e/0x5c > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] start_secondary+0x1b9/0x1be > > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 0 > > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 nvidia(P) [last unloaded: nvidia] > > May 11 10:05:00 ans-ebb3 kernel: > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c0570ab6>] EFLAGS: 00000807 CPU: 0 > > May 11 10:05:00 ans-ebb3 kernel: EIP is at delay_tsc+0x0/0x8a > > May 11 10:05:00 ans-ebb3 kernel: EAX: 001c7b29 EBX: 00000001 ECX: 04f29000 EDX: 001c7b28 > > May 11 10:05:00 ans-ebb3 kernel: ESI: 00000000 EDI: c084a6c0 EBP: c0828e6c ESP: c0828e68 > > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 preempt:04020002 > > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, ti=c0828000 task=c08407a0 task.ti=c0828000) > > May 11 10:05:00 ans-ebb3 kernel: Stack: > > May 11 10:05:00 ans-ebb3 kernel: c0570a4f c0828e78 c0418e84 c084a740 c0828eb0 c047c35b c07c1944 00000000 > > May 11 10:05:00 ans-ebb3 kernel: <0> 00002712 c5805268 c084a6c0 c084a6ec 00000003 c084a740 00000083 00000000 > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 c08407a0 c0828ec0 c047c45f 00000000 00000000 c0828ed4 c0441fbd > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > May 11 10:05:00 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] ? arch_trigger_all_cpu_backtrace+0x42/0x4f > > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] ? __rcu_pending+0x258/0x309 > > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] ? rcu_check_callbacks+0x53/0x114 > > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] ? update_process_times+0x32/0x43 > > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] ? tick_sched_timer+0x6d/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] ? __run_hrtimer+0xeb/0x154 > > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] ? hrtimer_interrupt+0xed/0x21e > > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] ? smp_apic_timer_interrupt+0xb4/0x106 > > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] ? apic_timer_interrupt+0x2a/0x30 > > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] ? cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] ? rest_init+0x80/0x82 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] ? start_kernel+0x2fb/0x300 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] ? i386_start_kernel+0x8c/0x91 > > May 11 10:05:01 ans-ebb3 kernel: Code: c0 8b 0c 8d 18 7b 87 c0 6b c0 14 ba 40 ff 8d c0 55 89 e5 69 94 0a 98 00 00 00 fa 00 00 00 f7 e2 8d 42 01 ff 15 90 84 85 c0 5d c3 <55> 89 e5 57 56 89 c6 53 83 ec 04 89 e0 25 00 f0 ff ff ff 40 14 > > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > > May 11 10:05:01 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f > > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 > > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 > > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 > > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 > > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e > > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 > > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 > > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 > > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 > > May 11 10:05:01 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P 2.6.33.2-rt13.11.trace #10 > > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > > May 11 10:05:01 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > > May 11 10:05:01 ans-ebb3 kernel: [<c06d0d7a>] nmi_watchdog_tick+0x9b/0x162 > > May 11 10:05:01 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > > May 11 10:05:01 ans-ebb3 kernel: [<c05645a8>] ? ltt_vtrace+0x0/0x79b > > May 11 10:05:02 ans-ebb3 kernel: [<c06cfd41>] nmi_stack_correct+0x28/0x2d > > May 11 10:05:02 ans-ebb3 kernel: [<c0570ab6>] ? delay_tsc+0x0/0x8a > > May 11 10:05:02 ans-ebb3 kernel: [<c0570a4f>] ? __const_udelay+0x2f/0x31 > > May 11 10:05:02 ans-ebb3 kernel: [<c0418e84>] arch_trigger_all_cpu_backtrace+0x42/0x4f > > May 11 10:05:02 ans-ebb3 kernel: [<c047c35b>] __rcu_pending+0x258/0x309 > > May 11 10:05:02 ans-ebb3 kernel: [<c047c45f>] rcu_check_callbacks+0x53/0x114 > > May 11 10:05:02 ans-ebb3 kernel: [<c0441fbd>] update_process_times+0x32/0x43 > > May 11 10:05:02 ans-ebb3 kernel: [<c04587b7>] tick_sched_timer+0x6d/0x9b > > May 11 10:05:02 ans-ebb3 kernel: [<c045874a>] ? tick_sched_timer+0x0/0x9b > > May 11 10:05:02 ans-ebb3 kernel: [<c044f8fc>] __run_hrtimer+0xeb/0x154 > > May 11 10:05:02 ans-ebb3 kernel: [<c044fc4d>] hrtimer_interrupt+0xed/0x21e > > May 11 10:05:02 ans-ebb3 kernel: [<c04518c5>] ? sched_clock_idle_wakeup_event+0x16/0x18 > > May 11 10:05:02 ans-ebb3 kernel: [<c0418512>] smp_apic_timer_interrupt+0xb4/0x106 > > May 11 10:05:02 ans-ebb3 kernel: [<c06cfa66>] apic_timer_interrupt+0x2a/0x30 > > May 11 10:05:02 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > May 11 10:05:02 ans-ebb3 kernel: [<c062e7c9>] cpuidle_idle_call+0x6c/0xdf > > May 11 10:05:02 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > May 11 10:05:02 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > > May 11 10:05:02 ans-ebb3 kernel: [<c087a859>] start_kernel+0x2fb/0x300 > > May 11 10:05:02 ans-ebb3 kernel: [<c087a08c>] i386_start_kernel+0x8c/0x91 > > > > > > > > -----Original Message----- > > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > > Sent: Tue 5/11/2010 7:59 AM > > To: John P. Paul > > Cc: ltt-dev at lists.casi.polymtl.ca > > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > > Hey Mathieu: > > > > > > Thanks for looking at this. I'm a bit new to debugging at this level, so > > > you may need to provide me a bit more info on what you need. I attempted > > > to use "pstack" on the lttctl and lttd tasks ... no luck as pstack also > > > locked up. > > > > > > I put a bit of tracing into liblttctl and discovered the lockup occurs > > > when a write of "traceName" (whatever traceName happens to be) occurs to > > > the "/mnt/debugfs/ltt/destroy_trace" file. > > > > > > I'm guessing that you would like some tracing of the ltt kernel module. > > > Is there something that I can turn on, or another way I could get a > > > stack dump of that module after lockup? I'll do a little research this > > > weekend on kernel debugging techniques. > > > > > > I can certainly sprinkle in some printk statements in the ltt kernel > > > module source. Doing provided the following info: > > > > > > - Control entered _ltt_trace_destroy (single underscore) > > > - Control entered del_timer_sync(<t_async_wakeup_timer) and never > > > returned > > > > > > Does that help, or should I continue farther down this path? > > > > Can you try the following patch to see if it fixes your problem ? > > > > > > lttng fix rt kernel teardown deadlock > > > > LTTng has a teardown bug on RT (deadlock): > > > > Deleting a timer (sync) while holding the traces mutex, and the handler takes > > the same mutex, which leads to a deadlock. > > > > Fix this by taking a RCU read lock in the timer (instead of the RT-specific fix > > using the mutex), and by doing synchronize_rcu() in addition to > > synchronize_sched() upon updates. > > > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > > --- > > ltt/ltt-tracer.c | 28 ++++++++++++++++++---------- > > 1 file changed, 18 insertions(+), 10 deletions(-) > > > > Index: linux-2.6-lttng/ltt/ltt-tracer.c > > =================================================================== > > --- linux-2.6-lttng.orig/ltt/ltt-tracer.c 2010-05-11 07:50:46.000000000 -0400 > > +++ linux-2.6-lttng/ltt/ltt-tracer.c 2010-05-11 07:55:46.000000000 -0400 > > @@ -41,6 +41,14 @@ > > #include <linux/vmalloc.h> > > #include <asm/atomic.h> > > > > +static void synchronize_trace(void) > > +{ > > + synchronize_sched(); > > +#ifdef CONFIG_PREEMPT_RT > > + synchronize_rcu(); > > +#endif > > +} > > + > > static void async_wakeup(unsigned long data); > > > > static DEFINE_TIMER(ltt_async_wakeup_timer, async_wakeup, 0, 0); > > @@ -321,7 +329,7 @@ void ltt_module_unregister(enum ltt_modu > > ltt_filter_unregister(); > > ltt_run_filter_owner = NULL; > > /* Wait for preempt sections to finish */ > > - synchronize_sched(); > > + synchronize_trace(); > > break; > > case LTT_FUNCTION_FILTER_CONTROL: > > ltt_filter_control_functor = ltt_filter_control_default; > > @@ -429,13 +437,13 @@ static void async_wakeup(unsigned long d > > * PREEMPT_RT does not allow spinlocks to be taken within preempt > > * disable sections (spinlock taken in wake_up). However, mainline won't > > * allow mutex to be taken in interrupt context. Ugly. > > - * A proper way to do this would be to turn the timer into a > > - * periodically woken up thread, but it adds to the footprint. > > + * Take a standard RCU read lock for RT kernels, which imply that we > > + * also have to synchronize_rcu() upon updates. > > */ > > #ifndef CONFIG_PREEMPT_RT > > rcu_read_lock_sched(); > > #else > > - ltt_lock_traces(); > > + rcu_read_lock(); > > #endif > > list_for_each_entry_rcu(trace, <t_traces.head, list) { > > trace_async_wakeup(trace); > > @@ -443,7 +451,7 @@ static void async_wakeup(unsigned long d > > #ifndef CONFIG_PREEMPT_RT > > rcu_read_unlock_sched(); > > #else > > - ltt_unlock_traces(); > > + rcu_read_unlock(); > > #endif > > > > mod_timer(<t_async_wakeup_timer, jiffies + LTT_PERCPU_TIMER_INTERVAL); > > @@ -901,7 +909,7 @@ int ltt_trace_alloc(const char *trace_na > > set_kernel_trace_flag_all_tasks(); > > } > > list_add_rcu(&trace->list, <t_traces.head); > > - synchronize_sched(); > > + synchronize_trace(); > > > > ltt_unlock_traces(); > > > > @@ -974,7 +982,7 @@ static int _ltt_trace_destroy(struct ltt > > } > > /* Everything went fine */ > > list_del_rcu(&trace->list); > > - synchronize_sched(); > > + synchronize_trace(); > > if (list_empty(<t_traces.head)) { > > clear_kernel_trace_flag_all_tasks(); > > /* > > @@ -1195,7 +1203,7 @@ static int _ltt_trace_stop(struct ltt_tr > > trace->nr_channels); > > trace->active = 0; > > ltt_traces.num_active_traces--; > > - synchronize_sched(); /* Wait for each tracing to be finished */ > > + synchronize_trace(); /* Wait for each tracing to be finished */ > > } > > module_put(ltt_run_filter_owner); > > /* Everything went fine */ > > @@ -1327,12 +1335,12 @@ static void __exit ltt_exit(void) > > list_for_each_entry_rcu(trace, <t_traces.head, list) > > _ltt_trace_stop(trace); > > /* Wait for quiescent state. Readers have preemption disabled. */ > > - synchronize_sched(); > > + synchronize_trace(); > > /* Safe iteration is now permitted. It does not have to be RCU-safe > > * because no readers are left. */ > > list_for_each_safe(pos, n, <t_traces.head) { > > trace = container_of(pos, struct ltt_trace, list); > > - /* _ltt_trace_destroy does a synchronize_sched() */ > > + /* _ltt_trace_destroy does a synchronize_trace() */ > > _ltt_trace_destroy(trace); > > __ltt_trace_destroy(trace); > > } > > > > > > > > -- > > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > > > > -- > Mathieu Desnoyers > Operating System Efficiency R&D Consultant > EfficiOS Inc. > http://www.efficios.com -- This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. ^ permalink raw reply [flat|nested] 10+ messages in thread
* [ltt-dev] lttctl locks up with RT Linux 2010-05-12 12:26 ` jpaul @ 2010-05-12 23:10 ` Paul E. McKenney 0 siblings, 0 replies; 10+ messages in thread From: Paul E. McKenney @ 2010-05-12 23:10 UTC (permalink / raw) Hello, John, Strange. I wonder where the other four call stacks are coming from. Thanx, Paul On Wed, May 12, 2010 at 08:26:01AM -0400, jpaul at gdrs.com wrote: > Hi Paul: > > I'm running on a single Intel Core 2 Duo. > > JP > > -----Original Message----- > From: Paul E. McKenney [mailto:paulmck@linux.vnet.ibm.com] > Sent: Tuesday, May 11, 2010 6:11 PM > To: Mathieu Desnoyers > Cc: John P. Paul; ltt-dev at lists.casi.polymtl.ca; > linux-rt-users at vger.kernel.org > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > On Tue, May 11, 2010 at 11:11:20AM -0400, Mathieu Desnoyers wrote: > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > > Thanks Mathieu. I'm going to have to look at this a bit more. This > may > > > have fixed one problem and cause another as "lttctl -C -w /tmp/trace > > > trace1" does not return and I'm getting a stack dump in the messages > > > file (see below). The last msg I see from that "lttctl -C" command > is > > > "lttctl: Creating trace". The "lttctl: Forking lttd" is not > displayed. > > > > If you disable RCU stalls detection, does it work ? > > > > [Context for Paul: it's on a -RT kernel, with the LTTng patchset] > > Strange. It looks like everyone is idle. > > Or is it possible that some CPU is spinning in an NMI handler? > > You have six call traces -- are there six CPUs online? > > Thanx, Paul > > > Thanks, > > > > Mathieu > > > > > > > > JP > > > > > > May 11 10:05:00 ans-ebb3 kernel: P5 > > > May 11 10:05:00 ans-ebb3 kernel: INFO: RCU detected CPU stalls: P5 > (detected by 0, t=10002 jiffies) > > > May 11 10:05:00 ans-ebb3 kernel: sending NMI to all CPUs: > > > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 1 > > > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc > ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror > sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp > iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 > e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 > nvidia(P) [last unloaded: nvidia] > > > May 11 10:05:00 ans-ebb3 kernel: > > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P > 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > > > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c062e4fa>] EFLAGS: > 00000246 CPU: 1 > > > May 11 10:05:00 ans-ebb3 kernel: EIP is at poll_idle+0x1e/0x5c > > > May 11 10:05:00 ans-ebb3 kernel: EAX: f74bc000 EBX: 6b655cfc ECX: > 6b655cfc EDX: 000001a2 > > > May 11 10:05:00 ans-ebb3 kernel: ESI: 000001a2 EDI: 00000000 EBP: > f74bcf84 ESP: f74bcf7c > > > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: > 0000 SS: 0068 preempt:04010002 > > > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, > ti=f74bc000 task=f74d90c0 task.ti=f74bc000) > > > May 11 10:05:00 ans-ebb3 kernel: Stack: > > > May 11 10:05:00 ans-ebb3 kernel: f765b02c f765b01c f74bcf94 > c062e7c9 00000001 c0877c90 f74bcfa4 c0401c0d > > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000001 00000000 f74bcfb0 > c06ca177 01020800 00000000 00000000 00000000 > > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 00000000 00000000 > 00000000 00000000 00000000 00000000 000000d8 > > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] ? > cpuidle_idle_call+0x6c/0xdf > > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] ? > start_secondary+0x1b9/0x1be > > > May 11 10:05:00 ans-ebb3 kernel: Code: ff ff ff 8d 65 f4 89 d8 5b 5e > 5f 5d c3 55 89 e5 56 53 e8 7b 61 e2 ff 89 c3 89 d6 fb 89 e0 25 00 f0 ff > ff eb 02 f3 90 f6 40 08 08 <74> f8 e8 60 61 e2 ff 29 d8 19 f2 e8 95 b6 > e0 ff b9 40 42 0f 00 > > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] > cpuidle_idle_call+0x6c/0xdf > > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] > start_secondary+0x1b9/0x1be > > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P > 2.6.33.2-rt13.11.trace #10 > > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > > May 11 10:05:00 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > > > May 11 10:05:00 ans-ebb3 kernel: [<c06d0d7a>] > nmi_watchdog_tick+0x9b/0x162 > > > May 11 10:05:00 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > > > May 11 10:05:00 ans-ebb3 kernel: [<c056355d>] ? > ltt_chan_for_each_channel+0x35/0x4f > > > May 11 10:05:00 ans-ebb3 kernel: [<c05628df>] ? > ltt_chanbuf_idle_switch+0x0/0x1c > > > May 11 10:05:00 ans-ebb3 kernel: [<c06cfd41>] > nmi_stack_correct+0x28/0x2d > > > May 11 10:05:00 ans-ebb3 kernel: [<c062e4fa>] ? poll_idle+0x1e/0x5c > > > May 11 10:05:00 ans-ebb3 kernel: [<c062e7c9>] > cpuidle_idle_call+0x6c/0xdf > > > May 11 10:05:00 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > > May 11 10:05:00 ans-ebb3 kernel: [<c06ca177>] > start_secondary+0x1b9/0x1be > > > May 11 10:05:00 ans-ebb3 kernel: NMI backtrace for cpu 0 > > > May 11 10:05:00 ans-ebb3 kernel: Modules linked in: battery sbshc > ehci_hcd sbs scsi_dh ohci_hcd dm_multipath uhci_hcd scsi_mod dm_mirror > sd_mod libata ahci dm_mod dm_log dm_region_hash tpm_bios tpm intel_agp > iTCO_vendor_support i2c_core pcspkr tpm_tis iTCO_wdt i2c_i801 autofs4 > e1000e button serio_raw sg output video ac parport lp parport_pc ipv6 > nvidia(P) [last unloaded: nvidia] > > > May 11 10:05:00 ans-ebb3 kernel: > > > May 11 10:05:00 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P > 2.6.33.2-rt13.11.trace #10 PXT /To Be Filled By O.E.M. > > > May 11 10:05:00 ans-ebb3 kernel: EIP: 0060:[<c0570ab6>] EFLAGS: > 00000807 CPU: 0 > > > May 11 10:05:00 ans-ebb3 kernel: EIP is at delay_tsc+0x0/0x8a > > > May 11 10:05:00 ans-ebb3 kernel: EAX: 001c7b29 EBX: 00000001 ECX: > 04f29000 EDX: 001c7b28 > > > May 11 10:05:00 ans-ebb3 kernel: ESI: 00000000 EDI: c084a6c0 EBP: > c0828e6c ESP: c0828e68 > > > May 11 10:05:00 ans-ebb3 kernel: DS: 007b ES: 007b FS: 00d8 GS: > 0000 SS: 0068 preempt:04020002 > > > May 11 10:05:00 ans-ebb3 kernel: Process swapper (pid: 0, > ti=c0828000 task=c08407a0 task.ti=c0828000) > > > May 11 10:05:00 ans-ebb3 kernel: Stack: > > > May 11 10:05:00 ans-ebb3 kernel: c0570a4f c0828e78 c0418e84 > c084a740 c0828eb0 c047c35b c07c1944 00000000 > > > May 11 10:05:00 ans-ebb3 kernel: <0> 00002712 c5805268 c084a6c0 > c084a6ec 00000003 c084a740 00000083 00000000 > > > May 11 10:05:00 ans-ebb3 kernel: <0> 00000000 c08407a0 c0828ec0 > c047c45f 00000000 00000000 c0828ed4 c0441fbd > > > May 11 10:05:00 ans-ebb3 kernel: Call Trace: > > > May 11 10:05:00 ans-ebb3 kernel: [<c0570a4f>] ? > __const_udelay+0x2f/0x31 > > > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] ? > arch_trigger_all_cpu_backtrace+0x42/0x4f > > > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] ? > __rcu_pending+0x258/0x309 > > > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] ? > rcu_check_callbacks+0x53/0x114 > > > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] ? > update_process_times+0x32/0x43 > > > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] ? > tick_sched_timer+0x6d/0x9b > > > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? > tick_sched_timer+0x0/0x9b > > > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] ? > __run_hrtimer+0xeb/0x154 > > > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] ? > hrtimer_interrupt+0xed/0x21e > > > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? > sched_clock_idle_wakeup_event+0x16/0x18 > > > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] ? > smp_apic_timer_interrupt+0xb4/0x106 > > > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] ? > apic_timer_interrupt+0x2a/0x30 > > > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] ? > cpuidle_idle_call+0x6c/0xdf > > > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] ? cpu_idle+0x49/0x80 > > > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] ? rest_init+0x80/0x82 > > > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] ? > start_kernel+0x2fb/0x300 > > > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] ? > i386_start_kernel+0x8c/0x91 > > > May 11 10:05:01 ans-ebb3 kernel: Code: c0 8b 0c 8d 18 7b 87 c0 6b c0 > 14 ba 40 ff 8d c0 55 89 e5 69 94 0a 98 00 00 00 fa 00 00 00 f7 e2 8d 42 > 01 ff 15 90 84 85 c0 5d c3 <55> 89 e5 57 56 89 c6 53 83 ec 04 89 e0 25 > 00 f0 ff ff ff 40 14 > > > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > > > May 11 10:05:01 ans-ebb3 kernel: [<c0570a4f>] ? > __const_udelay+0x2f/0x31 > > > May 11 10:05:01 ans-ebb3 kernel: [<c0418e84>] > arch_trigger_all_cpu_backtrace+0x42/0x4f > > > May 11 10:05:01 ans-ebb3 kernel: [<c047c35b>] > __rcu_pending+0x258/0x309 > > > May 11 10:05:01 ans-ebb3 kernel: [<c047c45f>] > rcu_check_callbacks+0x53/0x114 > > > May 11 10:05:01 ans-ebb3 kernel: [<c0441fbd>] > update_process_times+0x32/0x43 > > > May 11 10:05:01 ans-ebb3 kernel: [<c04587b7>] > tick_sched_timer+0x6d/0x9b > > > May 11 10:05:01 ans-ebb3 kernel: [<c045874a>] ? > tick_sched_timer+0x0/0x9b > > > May 11 10:05:01 ans-ebb3 kernel: [<c044f8fc>] > __run_hrtimer+0xeb/0x154 > > > May 11 10:05:01 ans-ebb3 kernel: [<c044fc4d>] > hrtimer_interrupt+0xed/0x21e > > > May 11 10:05:01 ans-ebb3 kernel: [<c04518c5>] ? > sched_clock_idle_wakeup_event+0x16/0x18 > > > May 11 10:05:01 ans-ebb3 kernel: [<c0418512>] > smp_apic_timer_interrupt+0xb4/0x106 > > > May 11 10:05:01 ans-ebb3 kernel: [<c06cfa66>] > apic_timer_interrupt+0x2a/0x30 > > > May 11 10:05:01 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > > May 11 10:05:01 ans-ebb3 kernel: [<c062e7c9>] > cpuidle_idle_call+0x6c/0xdf > > > May 11 10:05:01 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > > May 11 10:05:01 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > > > May 11 10:05:01 ans-ebb3 kernel: [<c087a859>] > start_kernel+0x2fb/0x300 > > > May 11 10:05:01 ans-ebb3 kernel: [<c087a08c>] > i386_start_kernel+0x8c/0x91 > > > May 11 10:05:01 ans-ebb3 kernel: Pid: 0, comm: swapper Tainted: P > 2.6.33.2-rt13.11.trace #10 > > > May 11 10:05:01 ans-ebb3 kernel: Call Trace: > > > May 11 10:05:01 ans-ebb3 kernel: [<c04019d4>] ? show_regs+0x1a/0x20 > > > May 11 10:05:01 ans-ebb3 kernel: [<c06d0d7a>] > nmi_watchdog_tick+0x9b/0x162 > > > May 11 10:05:01 ans-ebb3 kernel: [<c06d02e1>] do_nmi+0xd1/0x2e1 > > > May 11 10:05:01 ans-ebb3 kernel: [<c05645a8>] ? > ltt_vtrace+0x0/0x79b > > > May 11 10:05:02 ans-ebb3 kernel: [<c06cfd41>] > nmi_stack_correct+0x28/0x2d > > > May 11 10:05:02 ans-ebb3 kernel: [<c0570ab6>] ? delay_tsc+0x0/0x8a > > > May 11 10:05:02 ans-ebb3 kernel: [<c0570a4f>] ? > __const_udelay+0x2f/0x31 > > > May 11 10:05:02 ans-ebb3 kernel: [<c0418e84>] > arch_trigger_all_cpu_backtrace+0x42/0x4f > > > May 11 10:05:02 ans-ebb3 kernel: [<c047c35b>] > __rcu_pending+0x258/0x309 > > > May 11 10:05:02 ans-ebb3 kernel: [<c047c45f>] > rcu_check_callbacks+0x53/0x114 > > > May 11 10:05:02 ans-ebb3 kernel: [<c0441fbd>] > update_process_times+0x32/0x43 > > > May 11 10:05:02 ans-ebb3 kernel: [<c04587b7>] > tick_sched_timer+0x6d/0x9b > > > May 11 10:05:02 ans-ebb3 kernel: [<c045874a>] ? > tick_sched_timer+0x0/0x9b > > > May 11 10:05:02 ans-ebb3 kernel: [<c044f8fc>] > __run_hrtimer+0xeb/0x154 > > > May 11 10:05:02 ans-ebb3 kernel: [<c044fc4d>] > hrtimer_interrupt+0xed/0x21e > > > May 11 10:05:02 ans-ebb3 kernel: [<c04518c5>] ? > sched_clock_idle_wakeup_event+0x16/0x18 > > > May 11 10:05:02 ans-ebb3 kernel: [<c0418512>] > smp_apic_timer_interrupt+0xb4/0x106 > > > May 11 10:05:02 ans-ebb3 kernel: [<c06cfa66>] > apic_timer_interrupt+0x2a/0x30 > > > May 11 10:05:02 ans-ebb3 kernel: [<c062e4f6>] ? poll_idle+0x1a/0x5c > > > May 11 10:05:02 ans-ebb3 kernel: [<c062e7c9>] > cpuidle_idle_call+0x6c/0xdf > > > May 11 10:05:02 ans-ebb3 kernel: [<c0401c0d>] cpu_idle+0x49/0x80 > > > May 11 10:05:02 ans-ebb3 kernel: [<c06bdde4>] rest_init+0x80/0x82 > > > May 11 10:05:02 ans-ebb3 kernel: [<c087a859>] > start_kernel+0x2fb/0x300 > > > May 11 10:05:02 ans-ebb3 kernel: [<c087a08c>] > i386_start_kernel+0x8c/0x91 > > > > > > > > > > > > -----Original Message----- > > > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] > > > Sent: Tue 5/11/2010 7:59 AM > > > To: John P. Paul > > > Cc: ltt-dev at lists.casi.polymtl.ca > > > Subject: Re: [ltt-dev] lttctl locks up with RT Linux > > > > > > * jpaul at gdrs.com (jpaul at gdrs.com) wrote: > > > > Hey Mathieu: > > > > > > > > Thanks for looking at this. I'm a bit new to debugging at this > level, so > > > > you may need to provide me a bit more info on what you need. I > attempted > > > > to use "pstack" on the lttctl and lttd tasks ... no luck as pstack > also > > > > locked up. > > > > > > > > I put a bit of tracing into liblttctl and discovered the lockup > occurs > > > > when a write of "traceName" (whatever traceName happens to be) > occurs to > > > > the "/mnt/debugfs/ltt/destroy_trace" file. > > > > > > > > I'm guessing that you would like some tracing of the ltt kernel > module. > > > > Is there something that I can turn on, or another way I could get > a > > > > stack dump of that module after lockup? I'll do a little research > this > > > > weekend on kernel debugging techniques. > > > > > > > > I can certainly sprinkle in some printk statements in the ltt > kernel > > > > module source. Doing provided the following info: > > > > > > > > - Control entered _ltt_trace_destroy (single underscore) > > > > - Control entered del_timer_sync(<t_async_wakeup_timer) and > never > > > > returned > > > > > > > > Does that help, or should I continue farther down this path? > > > > > > Can you try the following patch to see if it fixes your problem ? > > > > > > > > > lttng fix rt kernel teardown deadlock > > > > > > LTTng has a teardown bug on RT (deadlock): > > > > > > Deleting a timer (sync) while holding the traces mutex, and the > handler takes > > > the same mutex, which leads to a deadlock. > > > > > > Fix this by taking a RCU read lock in the timer (instead of the > RT-specific fix > > > using the mutex), and by doing synchronize_rcu() in addition to > > > synchronize_sched() upon updates. > > > > > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com> > > > --- > > > ltt/ltt-tracer.c | 28 ++++++++++++++++++---------- > > > 1 file changed, 18 insertions(+), 10 deletions(-) > > > > > > Index: linux-2.6-lttng/ltt/ltt-tracer.c > > > =================================================================== > > > --- linux-2.6-lttng.orig/ltt/ltt-tracer.c 2010-05-11 > 07:50:46.000000000 -0400 > > > +++ linux-2.6-lttng/ltt/ltt-tracer.c 2010-05-11 > 07:55:46.000000000 -0400 > > > @@ -41,6 +41,14 @@ > > > #include <linux/vmalloc.h> > > > #include <asm/atomic.h> > > > > > > +static void synchronize_trace(void) > > > +{ > > > + synchronize_sched(); > > > +#ifdef CONFIG_PREEMPT_RT > > > + synchronize_rcu(); > > > +#endif > > > +} > > > + > > > static void async_wakeup(unsigned long data); > > > > > > static DEFINE_TIMER(ltt_async_wakeup_timer, async_wakeup, 0, 0); > > > @@ -321,7 +329,7 @@ void ltt_module_unregister(enum ltt_modu > > > ltt_filter_unregister(); > > > ltt_run_filter_owner = NULL; > > > /* Wait for preempt sections to finish */ > > > - synchronize_sched(); > > > + synchronize_trace(); > > > break; > > > case LTT_FUNCTION_FILTER_CONTROL: > > > ltt_filter_control_functor = ltt_filter_control_default; > > > @@ -429,13 +437,13 @@ static void async_wakeup(unsigned long d > > > * PREEMPT_RT does not allow spinlocks to be taken within > preempt > > > * disable sections (spinlock taken in wake_up). However, > mainline won't > > > * allow mutex to be taken in interrupt context. Ugly. > > > - * A proper way to do this would be to turn the timer into a > > > - * periodically woken up thread, but it adds to the footprint. > > > + * Take a standard RCU read lock for RT kernels, which imply > that we > > > + * also have to synchronize_rcu() upon updates. > > > */ > > > #ifndef CONFIG_PREEMPT_RT > > > rcu_read_lock_sched(); > > > #else > > > - ltt_lock_traces(); > > > + rcu_read_lock(); > > > #endif > > > list_for_each_entry_rcu(trace, <t_traces.head, list) { > > > trace_async_wakeup(trace); > > > @@ -443,7 +451,7 @@ static void async_wakeup(unsigned long d > > > #ifndef CONFIG_PREEMPT_RT > > > rcu_read_unlock_sched(); > > > #else > > > - ltt_unlock_traces(); > > > + rcu_read_unlock(); > > > #endif > > > > > > mod_timer(<t_async_wakeup_timer, jiffies + > LTT_PERCPU_TIMER_INTERVAL); > > > @@ -901,7 +909,7 @@ int ltt_trace_alloc(const char *trace_na > > > set_kernel_trace_flag_all_tasks(); > > > } > > > list_add_rcu(&trace->list, <t_traces.head); > > > - synchronize_sched(); > > > + synchronize_trace(); > > > > > > ltt_unlock_traces(); > > > > > > @@ -974,7 +982,7 @@ static int _ltt_trace_destroy(struct ltt > > > } > > > /* Everything went fine */ > > > list_del_rcu(&trace->list); > > > - synchronize_sched(); > > > + synchronize_trace(); > > > if (list_empty(<t_traces.head)) { > > > clear_kernel_trace_flag_all_tasks(); > > > /* > > > @@ -1195,7 +1203,7 @@ static int _ltt_trace_stop(struct ltt_tr > > > trace->nr_channels); > > > trace->active = 0; > > > ltt_traces.num_active_traces--; > > > - synchronize_sched(); /* Wait for each tracing to be > finished */ > > > + synchronize_trace(); /* Wait for each tracing to be > finished */ > > > } > > > module_put(ltt_run_filter_owner); > > > /* Everything went fine */ > > > @@ -1327,12 +1335,12 @@ static void __exit ltt_exit(void) > > > list_for_each_entry_rcu(trace, <t_traces.head, list) > > > _ltt_trace_stop(trace); > > > /* Wait for quiescent state. Readers have preemption disabled. > */ > > > - synchronize_sched(); > > > + synchronize_trace(); > > > /* Safe iteration is now permitted. It does not have to be > RCU-safe > > > * because no readers are left. */ > > > list_for_each_safe(pos, n, <t_traces.head) { > > > trace = container_of(pos, struct ltt_trace, list); > > > - /* _ltt_trace_destroy does a synchronize_sched() */ > > > + /* _ltt_trace_destroy does a synchronize_trace() */ > > > _ltt_trace_destroy(trace); > > > __ltt_trace_destroy(trace); > > > } > > > > > > > > > > > > -- > > > This is an e-mail from General Dynamics Robotic Systems. It is for > the intended recipient only and may contain confidential and privileged > information. No one else may read, print, store, copy, forward or act in > reliance on it or its attachments. If you are not the intended > recipient, please return this message to the sender and delete the > message and any attachments from your computer. Your cooperation is > appreciated. > > > > > > > -- > > Mathieu Desnoyers > > Operating System Efficiency R&D Consultant > > EfficiOS Inc. > > http://www.efficios.com > > -- > This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated. > ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2010-05-14 14:56 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <A47866F933DF804684068A24BF04A9730862A74C@gdrs-exchange.gdrs.com>
[not found] ` <20100422160601.GB28863@Krystal>
[not found] ` <A47866F933DF804684068A24BF04A97309116C93@gdrs-exchange.gdrs.com>
2010-05-11 11:59 ` [ltt-dev] lttctl locks up with RT Linux Mathieu Desnoyers
2010-05-11 14:50 ` jpaul
2010-05-11 15:11 ` Mathieu Desnoyers
2010-05-11 20:15 ` jpaul
2010-05-13 18:23 ` Mathieu Desnoyers
2010-05-14 14:33 ` jpaul
2010-05-14 14:56 ` Mathieu Desnoyers
2010-05-11 22:11 ` Paul E. McKenney
2010-05-12 12:26 ` jpaul
2010-05-12 23:10 ` Paul E. McKenney
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox