Description of problem: ftrace function_graph cause soft lockup Version-Release number of selected component (if applicable): 4.18.0-1.fc29.aarch64 96boards hikey (aka Hikey 620) 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: [ 2192.048976] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [kworker/0:1:13093] [ 2192.059999] Modules linked in: ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ir [ 2192.182233] dw_drm_dsi snd soundcore cpufreq_dt uas usb_storage adv7511 drm_kms_helpe] [ 2192.226217] CPU: 0 PID: 13093 Comm: kworker/0:1 Tainted: G E 4.18.0-1.f1 [ 2192.239385] Hardware name: LeMaker 96Boards LeMaker HiKey/96Boards LeMaker HiKey, BIOS8 [ 2192.253575] Workqueue: (null) (events_power_efficient) [ 2192.263410] pstate: 80400005 (Nzcv daif +PAN -UAO) [ 2192.270825] pc : __do_softirq+0x98/0x300 [ 2192.277061] lr : __do_softirq+0x64/0x300 [ 2192.283220] sp : ffff000008003ed0 [ 2192.288574] x29: ffff000008003ed0 x28: ffff800070021d40 [ 2192.297354] x27: ffff000008a1d640 x26: ffff000008004000 [ 2192.306125] x25: ffff000008000000 x24: ffff800005f1f000 [ 2192.314896] x23: 0000000000000040 x22: ffff00000eb1bc10 [ 2192.323663] x21: 0000000000000000 x20: 0000000000000027 [ 2192.332423] x19: ffff800070021d40 x18: 000000000000001d [ 2192.341186] x17: 0000000000000000 x16: 0000000000000000 [ 2192.349976] x15: 0000000000000001 x14: 0000000000000019 [ 2192.358750] x13: 0000000000000033 x12: 000000001c600000 [ 2192.367532] x11: ffff000008003b78 x10: 00000000000006d8 [ 2192.376302] x9 : ffff800005f0dc00 x8 : 0000000000000030 [ 2192.385072] x7 : ffff800005f09700 x6 : 00000000800e08c4 [ 2192.393852] x5 : 00000000ffffffff x4 : 0000000000000015 [ 2192.402628] x3 : 0000000000000000 x2 : 000000000000c8ce [ 2192.411408] x1 : 000080006ec84000 x0 : ffff00000923b8c0 [ 2192.420207] Call trace: [ 2192.424520] __do_softirq+0x98/0x300 [ 2192.430324] irq_exit+0xc0/0xd0 [ 2192.435541] __handle_domain_irq+0x70/0xc0 [ 2192.441985] gic_handle_irq+0x58/0xa8 [ 2192.447884] el1_irq+0xe8/0x180 [ 2192.453094] finish_task_switch+0x74/0x1f0 [ 2192.459573] __schedule+0x264/0x8b8 [ 2192.465239] schedule+0x30/0x88 [ 2192.470451] worker_thread+0xd0/0x400 [ 2192.476353] kthread+0x130/0x138 [ 2192.481664] ret_from_fork+0x10/0x18 Expected results: function_graph should work as expected Additional info:
FYI, this works fine on Raspberry Pi 3. [root@rpi3 tracing]# uname -r 4.18.0-1.fc29.aarch64 [root@rpi3 kernel-aarch64]# cd /sys/kernel/debug/tracing/ [root@rpi3 tracing]# cat available_tracers hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop [root@rpi3 tracing]# echo function_graph > current_tracer [root@rpi3 tracing]# [root@rpi3 tracing]# echo 1 > tracing_on [root@rpi3 tracing]# [root@rpi3 tracing]# cat trace | tail 1) + 44.219 us | } 2) 9.323 us | } 1) + 46.250 us | } 0) 0.365 us | dwc2_hcd_get_frame_number [dwc2](); 2) 0.208 us | unlock_page(); 1) 0.365 us | _raw_spin_lock_irqsave(); 0) 0.156 us | dwc2_hcd_select_transactions [dwc2](); 2) | alloc_set_pte() { 2) | add_mm_counter_fast() { 0) 8.385 us | }
Does this still happen with 5.3 kernels?
I just tested and confirm it works fine now [root@hikey ~]# uname -r 5.3.2-300.fc30.aarch64 [root@hikey ~]# cd /sys/kernel/debug/tracing/ [root@hikey tracing]# echo function_graph > current_tracer [root@hikey tracing]# echo 1 > tracing_on [root@hikey tracing]# cat trace | tail 7) 3.281 us | pcpu_next_unpop(); 0) | _cond_resched() { 0) 3.229 us | rcu_all_qs(); 7) 2.969 us | mutex_unlock(); 0) 9.271 us | } 0) 3.177 us | should_fail_alloc_page.isra.0(); 7) + 91.302 us | } 7) + 96.771 us | } 0) | get_page_from_freelist() { 0) | rmqueue_pcplist.isra.0() { No bug or warning message shows on console. Closing as current release.