Description of problem: ftrace function_graph cause soft lockup on raspberry pi 2. Version-Release number of selected component (if applicable): Raspberry Pi 2 4.18.0-1.fc29.armv7hl How reproducible: Always Steps to Reproduce: 1. cd /sys/kernel/debug/tracing/ 2. echo function_graph > current_tracer 3. echo 1 > tracing_on Actual results: Soft lockup happens like [ 548.007970] hrtimer: interrupt took 1233022 ns [ 558.041846] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 568.800716] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 579.033833] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 584.007064] watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [ksoftirqd/0:9] [ 584.016131] Modules linked in: nf_tables_set nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nfk [ 584.111034] dwc2 udc_core pwm_bcm2835 bcm2835 i2c_bcm2835 bcm2835_dma phy_generic [ 584.121527] CPU: 0 PID: 9 Comm: ksoftirqd/0 Not tainted 4.18.0-1.fc29.armv7hl #1 [ 584.130868] Hardware name: BCM2835 [ 584.135496] PC is at return_to_handler+0x0/0x18 [ 584.141454] LR is at ipv6_skip_exthdr+0x3c/0x150 [ 584.147481] pc : [<c03126fc>] lr : [<c0b291d8>] psr: a00d0013 [ 584.155472] sp : ef14f998 ip : c0b290dc fp : ef14f9c4 [ 584.162222] r10: d1af0a61 r9 : ef14f9ce r8 : ef14f9cd [ 584.168965] r7 : ebbf3800 r6 : 00000006 r5 : 00000028 r4 : c303b6c0 [ 584.177264] r3 : ffffffdb r2 : ef14f9cd r1 : 00000028 r0 : 00000000 [ 584.185564] Flags: NzCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none [ 584.220993] Control: 10c5387d Table: 2bb0806a DAC: 00000051 [ 584.255132] CPU: 0 PID: 9 Comm: ksoftirqd/0 Not tainted 4.18.0-1.fc29.armv7hl #1 [ 584.291119] Hardware name: BCM2835 [ 584.322656] [<c0313f7c>] (unwind_backtrace) from [<c03126fc>] (return_to_handler+0x0/0) [ 604.122506] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 614.874327] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 625.626735] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 635.866492] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 644.007065] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [kworker/0:3:516] [ 644.043039] Modules linked in: nf_tables_set nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nfk [ 644.403178] dwc2 udc_core pwm_bcm2835 bcm2835 i2c_bcm2835 bcm2835_dma phy_generic [ 644.440343] CPU: 0 PID: 516 Comm: kworker/0:3 Tainted: G L 4.18.0-1.fc21 [ 644.505763] Hardware name: BCM2835 [ 644.537605] Workqueue: events check_carrier [smsc95xx] [ 644.571270] PC is at trace_graph_return+0x98/0xa8 [ 644.604172] LR is at ring_buffer_unlock_commit+0x30/0xbc [ 644.637430] pc : [<c0433160>] lr : [<c0420804>] psr: 60090113 [ 644.671619] sp : ea42b9d0 ip : 00000b40 fp : ea42b9e4 [ 644.704424] r10: 00000000 r9 : 00000002 r8 : c1409600 [ 644.737178] r7 : 00000000 r6 : ea63f700 r5 : 00090113 r4 : ef6ed940 [ 644.771684] r3 : 00000000 r2 : 00000000 r1 : 00000000 r0 : 00000000 [ 644.806184] Flags: nZCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none [ 644.841449] Control: 10c5387d Table: 29e2c06a DAC: 00000051 [ 644.875073] CPU: 0 PID: 516 Comm: kworker/0:3 Tainted: G L 4.18.0-1.fc21 [ 644.939049] Hardware name: BCM2835 [ 644.970742] Workqueue: events check_carrier [smsc95xx] [ 645.004781] [<c0313f7c>] (unwind_backtrace) from [<c03126fc>] (return_to_handler+0x0/0) [ 646.118763] sdhost-bcm2835 3f202000.mmc: timeout waiting for hardware interrupt. [ 648.144234] ------------[ cut here ]------------ [ 648.158526] WARNING: CPU: 1 PID: 231 at drivers/mmc/host/bcm2835.c:899 bcm2835_threade] [ 648.187549] Modules linked in: nf_tables_set nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nfk [ 648.355094] dwc2 udc_core pwm_bcm2835 bcm2835 i2c_bcm2835 bcm2835_dma phy_generic [ 648.372886] CPU: 1 PID: 231 Comm: irq/80-mmc0 Tainted: G L 4.18.0-1.fc21 [ 648.401640] Hardware name: BCM2835 [ 648.414922] [<c0313f7c>] (unwind_backtrace) from [<c030dc64>] (show_stack+0x20/0x24) [ 648.432893] [<c030dc64>] (show_stack) from [<c0b48b84>] (dump_stack+0x88/0xa8) [ 648.450356] [<c0b48b84>] (dump_stack) from [<c0351858>] (__warn+0xe8/0x104) [ 648.467554] [<c0351858>] (__warn) from [<c0351bcc>] (warn_slowpath_null+0x4c/0x58) [ 648.485400] [<c0351bcc>] (warn_slowpath_null) from [<bf01ba6c>] (bcm2835_threaded_irq+) [ 648.515403] [<bf01ba6c>] (bcm2835_threaded_irq [bcm2835]) from [<c03b4174>] (irq_threa) [ 648.545111] [<c03b4174>] (irq_thread_fn) from [<c03b4454>] (irq_thread+0x148/0x1e8) [ 648.563445] [<c03b4454>] (irq_thread) from [<c0371524>] (kthread+0x150/0x168) [ 648.581072] [<c0371524>] (kthread) from [<c03010e8>] (ret_from_fork+0x14/0x2c) [ 648.598656] Exception stack(0xc32f9fb0 to 0xc32f9ff8) [ 648.613894] 9fa0: 00000000 00000000 00000000 000000 [ 648.642249] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000 [ 648.670728] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 648.688078] ---[ end trace a33fc983575c4a56 ]--- [ 648.702969] Unable to handle kernel NULL pointer dereference at virtual address 0000004 [ 648.731471] pgd = 76bf4cd9 [ 648.744207] [00000014] *pgd=00000000 [ 648.757747] Internal error: Oops: 5 [#1] SMP ARM [ 648.772000] Modules linked in: nf_tables_set nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nfk [ 648.942995] dwc2 udc_core pwm_bcm2835 bcm2835 i2c_bcm2835 bcm2835_dma phy_generic [ 648.961056] CPU: 0 PID: 516 Comm: kworker/0:3 Tainted: G W L 4.18.0-1.fc21 [ 648.990217] Hardware name: BCM2835 [ 649.003563] Workqueue: events bcm2835_dma_complete_work [bcm2835] [ 649.019660] PC is at bcm2835_finish_data+0x40/0xb0 [bcm2835] [ 649.035272] LR is at bcm2835_finish_data+0x34/0xb0 [bcm2835] [ 649.050704] pc : [<bf01b954>] lr : [<bf01b948>] psr: 60090013 [ 649.066736] sp : ea42bec0 ip : c031c0e0 fp : ea42bedc [ 649.081584] r10: 00000000 r9 : ee70cb74 r8 : c342e7a8 [ 649.096405] r7 : c0319720 r6 : ef314200 r5 : 00000000 r4 : ee70cb40 [ 649.112477] r3 : f1061000 r2 : 0000040e r1 : 00000000 r0 : ee70cb40 [ 649.128355] Flags: nZCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment none [ 649.144857] Control: 10c5387d Table: 29e2c06a DAC: 00000051 [ 649.159928] Process kworker/0:3 (pid: 516, stack limit = 0x33492ff5) [ 649.175539] Stack: (0xea42bec0 to 0xea42c000) [ 649.188933] bec0: ee70cb70 ee70cb44 ee70cb40 c0319720 ea42bf0c ea42bee0 bf01bce0 bf01b0 [ 649.215718] bee0: 00000000 00000000 c1411968 eaad7900 ee70cb70 ef6ea8c0 ef6edb00 000000 [ 649.243184] bf00: ea42bf44 ea42bf10 c036b670 bf01bbe4 0000008a e889bc52 00000096 eaad70 [ 649.270822] bf20: ef6ea8c0 ef6ea8c0 c1303d00 ef6ea8d8 eaad7914 00000008 ea42bf74 ea42b8 [ 649.298568] bf40: c036c43c c036b434 00000000 ea987d80 eaae0e40 ea42a000 eaad7900 c036c8 [ 649.326502] bf60: 00000000 ef147e98 ea42bfac ea42bf78 c0371524 c036c184 ea987d9c ea987c [ 649.354624] bf80: ea42bfac eaae0e40 c03713d4 00000000 00000000 00000000 00000000 000000 [ 649.382830] bfa0: 00000000 ea42bfb0 c03010e8 c03713e0 00000000 00000000 00000000 000000 [ 649.411234] bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000 [ 649.440207] bfe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 000000 [ 649.469948] [<bf01b954>] (bcm2835_finish_data [bcm2835]) from [<bf01bce0>] (bcm2835_dm) [ 649.503479] [<bf01bce0>] (bcm2835_dma_complete_work [bcm2835]) from [<c036b670>] (proc) [ 649.536238] [<c036b670>] (process_one_work) from [<c036c43c>] (worker_thread+0x2c4/0x4) [ 649.567460] [<c036c43c>] (worker_thread) from [<c0371524>] (kthread+0x150/0x168) [ 649.586620] [<c0371524>] (kthread) from [<c03010e8>] (ret_from_fork+0x14/0x2c) [ 649.605566] Exception stack(0xea42bfb0 to 0xea42bff8) [ 649.622241] bfa0: 00000000 00000000 00000000 000000 [ 649.653339] bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000 [ 649.684431] bfe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 649.702625] Code: eb4c01e0 e59420a4 e5943018 e5832038 (e5953014) [ 649.720703] ---[ end trace a33fc983575c4a57 ]--- Expected results: Ftrace function_graph tracer should work fine Additional info:
Does this still happen with 5.3 kernels?
Currently, I cannot test on my RPI2. I'll follow-up as soon as I can do a test there.
Well, function_graph tracer is disabled on RPI2 kernel, which means this is no longer reproducible. [root@rpi2 tracing]# uname -r 5.3.2-300.fc30.armv7hl [root@rpi2 tracing]# cat /sys/kernel/debug/tracing/available_tracers hwlat blk wakeup_dl wakeup_rt wakeup function nop I'll close as insufficient data in case function_graph tracer is enabled again later.