Le mardi 07 novembre 2017 à 11:13 +0100, Stanislaw Gruszka a écrit : > On Tue, Nov 07, 2017 at 11:06:39AM +0100, Richard Genoud wrote: > > > 3 short articles how to configure and use ftrace are here: > > > https://lwn.net/Articles/365835/ > > > https://lwn.net/Articles/366796/ > > > https://lwn.net/Articles/370423/ > > > > > > > I tried with ftrace, but I don't think there's a way to dump the > > trace > > when there's a soft lock-up > > (I can't do anything after the unbind, even the heartbeat led > > stopped blinking). > > I saw the /proc/sys/kernel/ftrace_dump_on_oops file, but there's no > > /proc/sys/kernel/ftrace_dump_on_soft_lock-up file :) > > You should configure function trace with rt2x* functions. After that > start tracing, unbind the device, then stop tracing and provide trace > output. Ok, I found a way to display the trace (after the unbind, the board is frozen and I can't type anything). Adding CONFIG_SOFTLOCKUP_DETECTOR=y CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC=y along with echo 1 > /proc/sys/kernel/ftrace_dump_on_oops does the trick (trace is after the stack dump) # cd /sys/kernel/debug/tracing/ # echo 1 > /proc/sys/kernel/ftrace_dump_on_oops # # echo rt2x00usb* > set_ftrace_filter # echo 0 > tracing_on # echo function > current_tracer # echo 1 > tracing_on # echo 1-2.2 > /sys/bus/usb/drivers/usb/unbind [board frozen] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [kworker/u2:3:188] CPU: 0 PID: 188 Comm: kworker/u2:3 Not tainted 4.14.0-rc8-00040-g53fb1fe423ba #13 Hardware name: Atmel AT91SAM9 Workqueue: phy0 rt2x00usb_work_rxdone task: c7b34400 task.stack: c7b4e000 PC is at rb_commit+0x1a8/0x2e4 LR is at ring_buffer_unlock_commit+0x20/0xa4 pc : [<c006c694>] lr : [<c006d724>] psr: 80000013 sp : c7b4fda8 ip : 00000000 fp : c7b4fdc4 r10: c664ee34 r9 : c7b2ed18 r8 : 60000013 r7 : 001c4851 r6 : c780a0e0 r5 : c7319340 r4 : 00008a48 r3 : c7319340 r2 : c664e000 r1 : 00000e38 r0 : 00000e24 Flags: Nzcv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none Control: 0005317f Table: 27270000 DAC: 00000053 CPU: 0 PID: 188 Comm: kworker/u2:3 Not tainted 4.14.0-rc8-00040-g53fb1fe423ba #13 Hardware name: Atmel AT91SAM9 Workqueue: phy0 rt2x00usb_work_rxdone [<c000fe00>] (unwind_backtrace) from [<c000dd94>] (show_stack+0x20/0x24) [<c000dd94>] (show_stack) from [<c05a55e0>] (dump_stack+0x20/0x28) [<c05a55e0>] (dump_stack) from [<c000b03c>] (show_regs+0x1c/0x20) [<c000b03c>] (show_regs) from [<c0064c90>] (watchdog_timer_fn+0x148/0x1ac) [<c0064c90>] (watchdog_timer_fn) from [<c0051dec>] (hrtimer_run_queues+0x128/0x250) [<c0051dec>] (hrtimer_run_queues) from [<c00512e8>] (run_local_timers+0x18/0x68) [<c00512e8>] (run_local_timers) from [<c0051370>] (update_process_times+0x38/0x6c) [<c0051370>] (update_process_times) from [<c005e1c0>] (tick_nohz_handler+0xc0/0x10c) [<c005e1c0>] (tick_nohz_handler) from [<c03a756c>] (ch2_irq+0x30/0x38) [<c03a756c>] (ch2_irq) from [<c0046b00>] (__handle_irq_event_percpu+0x74/0x1dc) [<c0046b00>] (__handle_irq_event_percpu) from [<c0046c94>] (handle_irq_event_percpu+0x2c/0x68) [<c0046c94>] (handle_irq_event_percpu) from [<c0046d08>] (handle_irq_event+0x38/0x4c) [<c0046d08>] (handle_irq_event) from [<c0049f54>] (handle_fasteoi_irq+0xa0/0x114) [<c0049f54>] (handle_fasteoi_irq) from [<c0046320>] (generic_handle_irq+0x28/0x38) [<c0046320>] (generic_handle_irq) from [<c00463c0>] (__handle_domain_irq+0x90/0xb8) [<c00463c0>] (__handle_domain_irq) from [<c00094a4>] (aic_handle+0xb0/0xb8) [<c00094a4>] (aic_handle) from [<c000ea68>] (__irq_svc+0x68/0x84) Exception stack(0xc7b4fd58 to 0xc7b4fda0) fd40: 00000e24 00000e38 fd60: c664e000 c7319340 00008a48 c7319340 c780a0e0 001c4851 60000013 c7b2ed18 fd80: c664ee34 c7b4fdc4 00000000 c7b4fda8 c006d724 c006c694 80000013 ffffffff [<c000ea68>] (__irq_svc) from [<c006c694>] (rb_commit+0x1a8/0x2e4) [<c006c694>] (rb_commit) from [<c006d724>] (ring_buffer_unlock_commit+0x20/0xa4) [<c006d724>] (ring_buffer_unlock_commit) from [<c00756f4>] (trace_function+0xe0/0xf0) [<c00756f4>] (trace_function) from [<c007c794>] (function_trace_call+0xbc/0x11c) [<c007c794>] (function_trace_call) from [<c000f12c>] (ftrace_graph_call+0x0/0xc) [<c000f12c>] (ftrace_graph_call) from [<c0337780>] (rt2x00usb_kick_rx_entry+0x14/0x118) [<c0337780>] (rt2x00usb_kick_rx_entry) from [<c033834c>] (rt2x00usb_clear_entry+0x30/0x34) [<c033834c>] (rt2x00usb_clear_entry) from [<c0332b10>] (rt2x00lib_rxdone+0x58c/0x5b8) [<c0332b10>] (rt2x00lib_rxdone) from [<c03376ec>] (rt2x00usb_work_rxdone+0x60/0x7c) [<c03376ec>] (rt2x00usb_work_rxdone) from [<c002ca64>] (process_one_work+0x1e4/0x3a0) [<c002ca64>] (process_one_work) from [<c002cf28>] (worker_thread+0x2c8/0x45c) [<c002cf28>] (worker_thread) from [<c0031f68>] (kthread+0x114/0x130) [<c0031f68>] (kthread) from [<c000a4c8>] (ret_from_fork+0x14/0x2c) Kernel panic - not syncing: softlockup: hung tasks CPU: 0 PID: 188 Comm: kworker/u2:3 Tainted: G L 4.14.0-rc8-00040-g53fb1fe423ba #13 Hardware name: Atmel AT91SAM9 Workqueue: phy0 rt2x00usb_work_rxdone [<c000fe00>] (unwind_backtrace) from [<c000dd94>] (show_stack+0x20/0x24) [<c000dd94>] (show_stack) from [<c05a55e0>] (dump_stack+0x20/0x28) [<c05a55e0>] (dump_stack) from [<c00187d0>] (panic+0xc8/0x260) [<c00187d0>] (panic) from [<c0064cc8>] (watchdog_timer_fn+0x180/0x1ac) [<c0064cc8>] (watchdog_timer_fn) from [<c0051dec>] (hrtimer_run_queues+0x128/0x250) [<c0051dec>] (hrtimer_run_queues) from [<c00512e8>] (run_local_timers+0x18/0x68) [<c00512e8>] (run_local_timers) from [<c0051370>] (update_process_times+0x38/0x6c) [<c0051370>] (update_process_times) from [<c005e1c0>] (tick_nohz_handler+0xc0/0x10c) [<c005e1c0>] (tick_nohz_handler) from [<c03a756c>] (ch2_irq+0x30/0x38) [<c03a756c>] (ch2_irq) from [<c0046b00>] (__handle_irq_event_percpu+0x74/0x1dc) [<c0046b00>] (__handle_irq_event_percpu) from [<c0046c94>] (handle_irq_event_percpu+0x2c/0x68) [<c0046c94>] (handle_irq_event_percpu) from [<c0046d08>] (handle_irq_event+0x38/0x4c) [<c0046d08>] (handle_irq_event) from [<c0049f54>] (handle_fasteoi_irq+0xa0/0x114) [<c0049f54>] (handle_fasteoi_irq) from [<c0046320>] (generic_handle_irq+0x28/0x38) [<c0046320>] (generic_handle_irq) from [<c00463c0>] (__handle_domain_irq+0x90/0xb8) [<c00463c0>] (__handle_domain_irq) from [<c00094a4>] (aic_handle+0xb0/0xb8) [<c00094a4>] (aic_handle) from [<c000ea68>] (__irq_svc+0x68/0x84) Exception stack(0xc7b4fd58 to 0xc7b4fda0) fd40: 00000e24 00000e38 fd60: c664e000 c7319340 00008a48 c7319340 c780a0e0 001c4851 60000013 c7b2ed18 fd80: c664ee34 c7b4fdc4 00000000 c7b4fda8 c006d724 c006c694 80000013 ffffffff [<c000ea68>] (__irq_svc) from [<c006c694>] (rb_commit+0x1a8/0x2e4) [<c006c694>] (rb_commit) from [<c006d724>] (ring_buffer_unlock_commit+0x20/0xa4) [<c006d724>] (ring_buffer_unlock_commit) from [<c00756f4>] (trace_function+0xe0/0xf0) [<c00756f4>] (trace_function) from [<c007c794>] (function_trace_call+0xbc/0x11c) [<c007c794>] (function_trace_call) from [<c000f12c>] (ftrace_graph_call+0x0/0xc) [<c000f12c>] (ftrace_graph_call) from [<c0337780>] (rt2x00usb_kick_rx_entry+0x14/0x118) [<c0337780>] (rt2x00usb_kick_rx_entry) from [<c033834c>] (rt2x00usb_clear_entry+0x30/0x34) [<c033834c>] (rt2x00usb_clear_entry) from [<c0332b10>] (rt2x00lib_rxdone+0x58c/0x5b8) [<c0332b10>] (rt2x00lib_rxdone) from [<c03376ec>] (rt2x00usb_work_rxdone+0x60/0x7c) [<c03376ec>] (rt2x00usb_work_rxdone) from [<c002ca64>] (process_one_work+0x1e4/0x3a0) [<c002ca64>] (process_one_work) from [<c002cf28>] (worker_thread+0x2c8/0x45c) [<c002cf28>] (worker_thread) from [<c0031f68>] (kthread+0x114/0x130) [<c0031f68>] (kthread) from [<c000a4c8>] (ret_from_fork+0x14/0x2c) Dumping ftrace buffer: --------------------------------- CPU:0 [LOST 1781327 EVENTS] kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone kworker/-188 0.n.. 24110000us : rt2x00usb_kick_rx_entry <-rt2x00usb_clear_entry kworker/-188 0.n.. 24110000us : rt2x00usb_clear_entry <-rt2x00lib_rxdone [forever] > Thanks > Stanislaw Thanks, Richard
