* 5.15 ftrace bug when enabling function_graph @ 2022-02-23 15:47 Daniel Dao 2022-02-23 16:54 ` Steven Rostedt 0 siblings, 1 reply; 7+ messages in thread From: Daniel Dao @ 2022-02-23 15:47 UTC (permalink / raw) To: rostedt; +Cc: kernel-team, mingo, linux-kernel Hi all We had some panic when trying to profile some function using ftrace's function_graph. The panic is attached here: ------------[ cut here ]------------ WARNING: CPU: 30 PID: 812411 at arch/x86/kernel/ftrace.c:96 ftrace_verify_code+0x37/0x70 Modules linked in: xt_hashlimit macvlan ip_set_hash_netport xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables ip6table_filter ip6table_mangle ip6table_raw ip6table_security ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul crc32c_intel aesni_intel rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] CPU: 30 PID: 812411 Comm: bash Tainted: G O 5.15.19-cloudflare-2022.2.1 #1 Hardware name: Quanta Cloud Technology Inc. QuantaPlex T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 RIP: 0010:ftrace_verify_code+0x37/0x70 Code: 83 ec 10 65 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 8d 7c 24 03 e8 26 1f 1a 00 48 85 c0 75 33 8b 03 39 44 24 03 74 1d <0f> 0b b8 ea ff ff ff 48 8b 4c 24 08 65 48 2b 0c 25 28 00 00 00 75 RSP: 0018:ffffa86ce19e3d28 EFLAGS: 00010212 RAX: 0000000000441f0f RBX: ffffffffa9001e8a RCX: 0000000000000010 RDX: 000000000db62b18 RSI: 0000000000000005 RDI: ffffffffa89ea1d0 RBP: ffffffffaa764350 R08: 0000000000000001 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000001 R13: ffff8fb8c00f95f0 R14: 0000000000000000 R15: 000000000000000f FS: 00007f3715044740(0000) GS:ffff8ff7bf380000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 000055c306a30298 CR3: 0000002e01756002 CR4: 00000000007706e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 PKRU: 55555554 Call Trace: <TASK> ftrace_replace_code+0x9a/0x160 ? arch_unoptimize_kprobes+0xb0/0xb0 ftrace_modify_all_code+0xbd/0x150 ftrace_run_update_code+0x13/0x70 ftrace_startup.part.0+0xe1/0x140 register_ftrace_graph+0x292/0x2d0 graph_trace_init+0x27/0x50 tracing_set_tracer+0xdb/0x170 tracing_set_trace_write+0x95/0xe0 vfs_write+0xbd/0x270 ksys_write+0x5f/0xe0 do_syscall_64+0x38/0x90 entry_SYSCALL_64_after_hwframe+0x44/0xae RIP: 0033:0x7f3715135f33 Code: 8b 15 61 ef 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 RSP: 002b:00007ffc4232a038 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f3715135f33 RDX: 000000000000000f RSI: 000055c2f4c63480 RDI: 0000000000000001 RBP: 000055c2f4c63480 R08: 000000000000000a R09: 000000000000000e R10: 000055c2f4c66cd0 R11: 0000000000000246 R12: 000000000000000f R13: 00007f37152066a0 R14: 000000000000000f R15: 00007f37152068a0 </TASK> ---[ end trace 3c0096669fc25320 ]--- ------------[ ftrace bug ]------------ ftrace failed to modify [<ffffffffa89ea1d0>] bpf_dispatcher_xdp_func+0x0/0x10 actual: ffffffe9:2b:ffffffb6:0d:18 Setting ftrace call site to call ftrace function ftrace record flags: 10000001 (1) expected tramp: ffffffffa824bd90 ------------[ cut here ]------------ After this, any attempt to use trace will fail. For example, here we execute https://github.com/iovisor/bcc/blob/master/tools/funcslower.py shortly after. WARNING: CPU: 30 PID: 812411 at kernel/trace/ftrace.c:2073 ftrace_bug+0x22c/0x252 Modules linked in: xt_hashlimit macvlan ip_set_hash_netport xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables ip6table_filter ip6table_mangle ip6table_raw ip6table_security ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul crc32c_intel aesni_intel rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] CPU: 30 PID: 812411 Comm: bash Tainted: G W O 5.15.19-cloudflare-2022.2.1 #1 Hardware name: Quanta Cloud Technology Inc. QuantaPlex T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 RIP: 0010:ftrace_bug+0x22c/0x252 Code: ff 84 c0 74 d0 eb b4 48 c7 c7 d8 72 75 a9 e8 53 c9 ff ff 48 89 ef e8 5b 74 7b ff 48 c7 c7 e9 72 75 a9 48 89 c6 e8 3c c9 ff ff <0f> 0b c7 05 18 98 4d 01 01 00 00 00 5b c7 05 1d 98 4d 01 00 00 00 RSP: 0018:ffffa86ce19e3d50 EFLAGS: 00010246 RAX: 0000000000000022 RBX: 00000000ffffffea RCX: ffff8ff7bf39f7b8 RDX: 0000000000000000 RSI: 0000000000000027 RDI: ffff8ff7bf39f7b0 RBP: ffff8fb8c00f95f0 R08: ffffffffaa719120 R09: 000000000000000f R10: 000000000000000f R11: ffff8ff83ff3291a R12: ffffffffa89ea1d0 R13: ffffffffa8250030 R14: 0000000000000000 R15: 000000000000000f FS: 00007f3715044740(0000) GS:ffff8ff7bf380000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 000055c306a30298 CR3: 0000002e01756002 CR4: 00000000007706e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 PKRU: 55555554 Call Trace: <TASK> ftrace_modify_all_code+0xbd/0x150 ftrace_run_update_code+0x13/0x70 ftrace_startup.part.0+0xe1/0x140 register_ftrace_graph+0x292/0x2d0 graph_trace_init+0x27/0x50 tracing_set_tracer+0xdb/0x170 tracing_set_trace_write+0x95/0xe0 vfs_write+0xbd/0x270 ksys_write+0x5f/0xe0 do_syscall_64+0x38/0x90 entry_SYSCALL_64_after_hwframe+0x44/0xae RIP: 0033:0x7f3715135f33 Code: 8b 15 61 ef 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 RSP: 002b:00007ffc4232a038 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f3715135f33 RDX: 000000000000000f RSI: 000055c2f4c63480 RDI: 0000000000000001 RBP: 000055c2f4c63480 R08: 000000000000000a R09: 000000000000000e R10: 000055c2f4c66cd0 R11: 0000000000000246 R12: 000000000000000f R13: 00007f37152066a0 R14: 000000000000000f R15: 00007f37152068a0 </TASK> ---[ end trace 3c0096669fc25321 ]--- BUG: kernel NULL pointer dereference, address: 0000000000000000 #PF: supervisor read access in kernel mode #PF: error_code(0x0000) - not-present page PGD f607b5067 P4D f607b5067 PUD ef47e0067 PMD 0 Oops: 0000 [#1] SMP NOPTI CPU: 4 PID: 852378 Comm: funcslower Tainted: G W O 5.15.19-cloudflare-2022.2.1 #1 Hardware name: Quanta Cloud Technology Inc. QuantaPlex T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 RIP: 0010:register_kprobe+0xb8/0x630 Code: aa 48 85 c0 75 0a eb 4a 48 8b 00 48 85 c0 74 42 48 3b 50 28 75 f2 48 39 c5 74 21 48 8b 70 10 48 8d 56 f0 48 39 d0 75 0f eb 28 <48> 8b 52 10 48 83 ea 10 48 39 d0 74 1b 48 39 d5 75 ee 0f 0b 48 c7 RSP: 0000:ffffa86cf5313d58 EFLAGS: 00010287 RAX: ffff8fc570aa3a40 RBX: 0000000000000000 RCX: 0000000000000000 RDX: fffffffffffffff0 RSI: ffff8fcf34e45a28 RDI: ffff8fca4f652700 RBP: ffff8fb9f851f918 R08: 0000000000000006 R09: ffff8fb8c7e680e8 R10: 0000000000000000 R11: 000000000000005d R12: 0000000000000000 R13: ffff8fc5d1c5c860 R14: ffff8fb9f851f9d8 R15: 0000000000000000 FS: 00007fa26c8a0740(0000) GS:ffff8fd7bf700000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 0000000000000000 CR3: 0000001be733e003 CR4: 00000000007706e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 PKRU: 55555554 Call Trace: <TASK> __trace_kprobe_create+0x810/0xb10 ? __kmalloc+0x17e/0x320 ? print_kprobe_event+0x190/0x190 ? probes_write+0x10/0x10 trace_probe_create+0x73/0x90 create_or_delete_trace_kprobe+0x11/0x30 trace_parse_run_command+0xba/0x140 vfs_write+0xbd/0x270 ksys_write+0x5f/0xe0 do_syscall_64+0x38/0x90 entry_SYSCALL_64_after_hwframe+0x44/0xae RIP: 0033:0x7fa26cc17fb3 Code: 75 05 48 83 c4 58 c3 e8 cb 41 ff ff 66 2e 0f 1f 84 00 00 00 00 00 90 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 RSP: 002b:00007ffdf1336128 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa26cc17fb3 RDX: 0000000000000044 RSI: 00007ffdf1336470 RDI: 0000000000000007 RBP: 00007ffdf1336470 R08: 00000000ffffffff R09: 00007ffdf1335fb0 R10: 00007fa263400090 R11: 0000000000000246 R12: 00007fa26bd150b9 R13: 0000000000000007 R14: 00007fa263400490 R15: 00007ffdf1336150 </TASK> Modules linked in: xt_hashlimit macvlan ip_set_hash_netport xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables ip6table_filter ip6table_mangle ip6table_raw ip6table_security ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul crc32c_intel aesni_intel rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] CR2: 0000000000000000 ---[ end trace 3c0096669fc25323 ]--- RIP: 0010:register_kprobe+0xb8/0x630 Code: aa 48 85 c0 75 0a eb 4a 48 8b 00 48 85 c0 74 42 48 3b 50 28 75 f2 48 39 c5 74 21 48 8b 70 10 48 8d 56 f0 48 39 d0 75 0f eb 28 <48> 8b 52 10 48 83 ea 10 48 39 d0 74 1b 48 39 d5 75 ee 0f 0b 48 c7 RSP: 0000:ffffa86cf5313d58 EFLAGS: 00010287 RAX: ffff8fc570aa3a40 RBX: 0000000000000000 RCX: 0000000000000000 RDX: fffffffffffffff0 RSI: ffff8fcf34e45a28 RDI: ffff8fca4f652700 RBP: ffff8fb9f851f918 R08: 0000000000000006 R09: ffff8fb8c7e680e8 R10: 0000000000000000 R11: 000000000000005d R12: 0000000000000000 R13: ffff8fc5d1c5c860 R14: ffff8fb9f851f9d8 R15: 0000000000000000 FS: 00007fa26c8a0740(0000) GS:ffff8fd7bf700000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 0000000000000000 CR3: 0000001be733e003 CR4: 00000000007706e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 PKRU: 55555554 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 5.15 ftrace bug when enabling function_graph 2022-02-23 15:47 5.15 ftrace bug when enabling function_graph Daniel Dao @ 2022-02-23 16:54 ` Steven Rostedt 2022-08-05 18:37 ` Ivan Babrou 0 siblings, 1 reply; 7+ messages in thread From: Steven Rostedt @ 2022-02-23 16:54 UTC (permalink / raw) To: Daniel Dao; +Cc: kernel-team, mingo, linux-kernel, Masami Hiramatsu On Wed, 23 Feb 2022 15:47:28 +0000 Daniel Dao <dqminh@cloudflare.com> wrote: > Hi all > > We had some panic when trying to profile some function using ftrace's > function_graph. > The panic is attached here: > > ------------[ cut here ]------------ > WARNING: CPU: 30 PID: 812411 at arch/x86/kernel/ftrace.c:96 > ftrace_verify_code+0x37/0x70 > Modules linked in: xt_hashlimit macvlan ip_set_hash_netport > xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen > nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 > ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit > tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun > overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder > tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables > ip6table_filter ip6table_mangle ip6table_raw ip6table_security > ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter > xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack > iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment > xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set > nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 > 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm > irqbypass crc32_pclmul crc32c_intel aesni_intel > rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus > xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd > ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button > ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables > bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] > CPU: 30 PID: 812411 Comm: bash Tainted: G O > 5.15.19-cloudflare-2022.2.1 #1 > Hardware name: Quanta Cloud Technology Inc. QuantaPlex > T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 > RIP: 0010:ftrace_verify_code+0x37/0x70 > Code: 83 ec 10 65 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 8d > 7c 24 03 e8 26 1f 1a 00 48 85 c0 75 33 8b 03 39 44 24 03 74 1d <0f> 0b > b8 ea ff ff ff 48 8b 4c 24 08 65 48 2b 0c 25 28 00 00 00 75 > RSP: 0018:ffffa86ce19e3d28 EFLAGS: 00010212 > RAX: 0000000000441f0f RBX: ffffffffa9001e8a RCX: 0000000000000010 > RDX: 000000000db62b18 RSI: 0000000000000005 RDI: ffffffffa89ea1d0 > RBP: ffffffffaa764350 R08: 0000000000000001 R09: 0000000000000000 > R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000001 > R13: ffff8fb8c00f95f0 R14: 0000000000000000 R15: 000000000000000f > FS: 00007f3715044740(0000) GS:ffff8ff7bf380000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 000055c306a30298 CR3: 0000002e01756002 CR4: 00000000007706e0 > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > PKRU: 55555554 > Call Trace: > <TASK> > ftrace_replace_code+0x9a/0x160 > ? arch_unoptimize_kprobes+0xb0/0xb0 > ftrace_modify_all_code+0xbd/0x150 > ftrace_run_update_code+0x13/0x70 > ftrace_startup.part.0+0xe1/0x140 > register_ftrace_graph+0x292/0x2d0 > graph_trace_init+0x27/0x50 > tracing_set_tracer+0xdb/0x170 > tracing_set_trace_write+0x95/0xe0 > vfs_write+0xbd/0x270 > ksys_write+0x5f/0xe0 > do_syscall_64+0x38/0x90 > entry_SYSCALL_64_after_hwframe+0x44/0xae > RIP: 0033:0x7f3715135f33 > Code: 8b 15 61 ef 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f > 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d > 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 > RSP: 002b:00007ffc4232a038 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 > RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f3715135f33 > RDX: 000000000000000f RSI: 000055c2f4c63480 RDI: 0000000000000001 > RBP: 000055c2f4c63480 R08: 000000000000000a R09: 000000000000000e > R10: 000055c2f4c66cd0 R11: 0000000000000246 R12: 000000000000000f > R13: 00007f37152066a0 R14: 000000000000000f R15: 00007f37152068a0 > </TASK> > ---[ end trace 3c0096669fc25320 ]--- > ------------[ ftrace bug ]------------ > ftrace failed to modify > [<ffffffffa89ea1d0>] bpf_dispatcher_xdp_func+0x0/0x10 Of course this is bpf :-/ OK, I found the creation of bpf_dispatcher_xdp_func in include/linux/bpf.h: #define DEFINE_BPF_DISPATCHER(name) \ noinline __nocfi unsigned int bpf_dispatcher_##name##_func( \ const void *ctx, \ const struct bpf_insn *insnsi, \ unsigned int (*bpf_func)(const void *, \ const struct bpf_insn *)) \ { \ return bpf_func(ctx, insnsi); \ } \ You can try changing that to: noinline __nocfi notrace unsigned int bpf_dispatcher_##name##_func( \ and see if that fixes it for you. If you can not change the running kernel, you can try this first: # echo 'bpf_dispatcher_*_func' > /sys/kernel/tracing/set_ftrace_notrace It doesn't explain the bug, but at least may be a workaround for you. > actual: ffffffe9:2b:ffffffb6:0d:18 Bah, I need to make that an unsigned char for printing. That was to be: e9:2b:b6:0d:18 Unfortunately, we lost what it expected to see due to changes in the modification code, so I do not really know what the problem was :-/ > Setting ftrace call site to call ftrace function > ftrace record flags: 10000001 So the record says that there's a trampoline used for the callback, and that there's one user. That makes sense. > (1) > expected tramp: ffffffffa824bd90 So this the location of the trampoline. As the instruction is e92bb60d18 Where e9 is the call, and the rest is the offset from the RIP which is: ffffffffa89ea1d0 (from above) ffffffffa89ea1d0 + 2bb60d18 + 5 (for instruction size) should give: Which would give: ffffffffd454aeed Which is not the trampoline. The jump to the trampoline should have it be: e9861bc0 If I did my addition correctly, as the trampoline is at a lower location than the address of the function. > ------------[ cut here ]------------ > > After this, any attempt to use trace will fail. For example, here we execute > https://github.com/iovisor/bcc/blob/master/tools/funcslower.py shortly after. > > WARNING: CPU: 30 PID: 812411 at kernel/trace/ftrace.c:2073 > ftrace_bug+0x22c/0x252 OK, so once a ftrace_bug is hit, ftrace is "shutdown". No more modifications is done due to the fact that the accounting has no integrity. > Modules linked in: xt_hashlimit macvlan ip_set_hash_netport > xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen > nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 > ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit > tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun > overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder > tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables > ip6table_filter ip6table_mangle ip6table_raw ip6table_security > ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter > xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack > iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment > xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set > nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 > 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm > irqbypass crc32_pclmul crc32c_intel aesni_intel > rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus > xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd > ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button > ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables > bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] > CPU: 30 PID: 812411 Comm: bash Tainted: G W O > 5.15.19-cloudflare-2022.2.1 #1 > Hardware name: Quanta Cloud Technology Inc. QuantaPlex > T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 > RIP: 0010:ftrace_bug+0x22c/0x252 > Code: ff 84 c0 74 d0 eb b4 48 c7 c7 d8 72 75 a9 e8 53 c9 ff ff 48 89 > ef e8 5b 74 7b ff 48 c7 c7 e9 72 75 a9 48 89 c6 e8 3c c9 ff ff <0f> 0b > c7 05 18 98 4d 01 01 00 00 00 5b c7 05 1d 98 4d 01 00 00 00 > RSP: 0018:ffffa86ce19e3d50 EFLAGS: 00010246 > RAX: 0000000000000022 RBX: 00000000ffffffea RCX: ffff8ff7bf39f7b8 > RDX: 0000000000000000 RSI: 0000000000000027 RDI: ffff8ff7bf39f7b0 > RBP: ffff8fb8c00f95f0 R08: ffffffffaa719120 R09: 000000000000000f > R10: 000000000000000f R11: ffff8ff83ff3291a R12: ffffffffa89ea1d0 > R13: ffffffffa8250030 R14: 0000000000000000 R15: 000000000000000f > FS: 00007f3715044740(0000) GS:ffff8ff7bf380000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 000055c306a30298 CR3: 0000002e01756002 CR4: 00000000007706e0 > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > PKRU: 55555554 > Call Trace: > <TASK> > ftrace_modify_all_code+0xbd/0x150 > ftrace_run_update_code+0x13/0x70 > ftrace_startup.part.0+0xe1/0x140 > register_ftrace_graph+0x292/0x2d0 > graph_trace_init+0x27/0x50 > tracing_set_tracer+0xdb/0x170 > tracing_set_trace_write+0x95/0xe0 > vfs_write+0xbd/0x270 > ksys_write+0x5f/0xe0 > do_syscall_64+0x38/0x90 > entry_SYSCALL_64_after_hwframe+0x44/0xae > RIP: 0033:0x7f3715135f33 > Code: 8b 15 61 ef 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f > 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d > 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 > RSP: 002b:00007ffc4232a038 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 > RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f3715135f33 > RDX: 000000000000000f RSI: 000055c2f4c63480 RDI: 0000000000000001 > RBP: 000055c2f4c63480 R08: 000000000000000a R09: 000000000000000e > R10: 000055c2f4c66cd0 R11: 0000000000000246 R12: 000000000000000f > R13: 00007f37152066a0 R14: 000000000000000f R15: 00007f37152068a0 > </TASK> > ---[ end trace 3c0096669fc25321 ]--- > BUG: kernel NULL pointer dereference, address: 0000000000000000 > #PF: supervisor read access in kernel mode > #PF: error_code(0x0000) - not-present page > PGD f607b5067 P4D f607b5067 PUD ef47e0067 PMD 0 > Oops: 0000 [#1] SMP NOPTI > CPU: 4 PID: 852378 Comm: funcslower Tainted: G W O > 5.15.19-cloudflare-2022.2.1 #1 > Hardware name: Quanta Cloud Technology Inc. QuantaPlex > T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 > RIP: 0010:register_kprobe+0xb8/0x630 > Code: aa 48 85 c0 75 0a eb 4a 48 8b 00 48 85 c0 74 42 48 3b 50 28 75 > f2 48 39 c5 74 21 48 8b 70 10 48 8d 56 f0 48 39 d0 75 0f eb 28 <48> 8b > 52 10 48 83 ea 10 48 39 d0 74 1b 48 39 d5 75 ee 0f 0b 48 c7 > RSP: 0000:ffffa86cf5313d58 EFLAGS: 00010287 > RAX: ffff8fc570aa3a40 RBX: 0000000000000000 RCX: 0000000000000000 > RDX: fffffffffffffff0 RSI: ffff8fcf34e45a28 RDI: ffff8fca4f652700 > RBP: ffff8fb9f851f918 R08: 0000000000000006 R09: ffff8fb8c7e680e8 > R10: 0000000000000000 R11: 000000000000005d R12: 0000000000000000 > R13: ffff8fc5d1c5c860 R14: ffff8fb9f851f9d8 R15: 0000000000000000 > FS: 00007fa26c8a0740(0000) GS:ffff8fd7bf700000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 0000000000000000 CR3: 0000001be733e003 CR4: 00000000007706e0 > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > PKRU: 55555554 > Call Trace: > <TASK> > __trace_kprobe_create+0x810/0xb10 OK, I'm guessing that something got messed up with the kprobe code when a kprobe failed to arm. Perhaps not everything is cleaned up properly? Masami? -- Steve > ? __kmalloc+0x17e/0x320 > ? print_kprobe_event+0x190/0x190 > ? probes_write+0x10/0x10 > trace_probe_create+0x73/0x90 > create_or_delete_trace_kprobe+0x11/0x30 > trace_parse_run_command+0xba/0x140 > vfs_write+0xbd/0x270 > ksys_write+0x5f/0xe0 > do_syscall_64+0x38/0x90 > entry_SYSCALL_64_after_hwframe+0x44/0xae > RIP: 0033:0x7fa26cc17fb3 > Code: 75 05 48 83 c4 58 c3 e8 cb 41 ff ff 66 2e 0f 1f 84 00 00 00 00 > 00 90 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d > 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 > RSP: 002b:00007ffdf1336128 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 > RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa26cc17fb3 > RDX: 0000000000000044 RSI: 00007ffdf1336470 RDI: 0000000000000007 > RBP: 00007ffdf1336470 R08: 00000000ffffffff R09: 00007ffdf1335fb0 > R10: 00007fa263400090 R11: 0000000000000246 R12: 00007fa26bd150b9 > R13: 0000000000000007 R14: 00007fa263400490 R15: 00007ffdf1336150 > </TASK> > Modules linked in: xt_hashlimit macvlan ip_set_hash_netport > xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen > nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 > ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit > tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun > overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder > tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables > ip6table_filter ip6table_mangle ip6table_raw ip6table_security > ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter > xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack > iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment > xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set > nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 > 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm > irqbypass crc32_pclmul crc32c_intel aesni_intel > rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus > xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd > ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button > ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables > bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] > CR2: 0000000000000000 > ---[ end trace 3c0096669fc25323 ]--- > RIP: 0010:register_kprobe+0xb8/0x630 > Code: aa 48 85 c0 75 0a eb 4a 48 8b 00 48 85 c0 74 42 48 3b 50 28 75 > f2 48 39 c5 74 21 48 8b 70 10 48 8d 56 f0 48 39 d0 75 0f eb 28 <48> 8b > 52 10 48 83 ea 10 48 39 d0 74 1b 48 39 d5 75 ee 0f 0b 48 c7 > RSP: 0000:ffffa86cf5313d58 EFLAGS: 00010287 > RAX: ffff8fc570aa3a40 RBX: 0000000000000000 RCX: 0000000000000000 > RDX: fffffffffffffff0 RSI: ffff8fcf34e45a28 RDI: ffff8fca4f652700 > RBP: ffff8fb9f851f918 R08: 0000000000000006 R09: ffff8fb8c7e680e8 > R10: 0000000000000000 R11: 000000000000005d R12: 0000000000000000 > R13: ffff8fc5d1c5c860 R14: ffff8fb9f851f9d8 R15: 0000000000000000 > FS: 00007fa26c8a0740(0000) GS:ffff8fd7bf700000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 0000000000000000 CR3: 0000001be733e003 CR4: 00000000007706e0 > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > PKRU: 55555554 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 5.15 ftrace bug when enabling function_graph 2022-02-23 16:54 ` Steven Rostedt @ 2022-08-05 18:37 ` Ivan Babrou 2022-08-05 18:53 ` Steven Rostedt 0 siblings, 1 reply; 7+ messages in thread From: Ivan Babrou @ 2022-08-05 18:37 UTC (permalink / raw) To: Steven Rostedt Cc: Daniel Dao, kernel-team, Ingo Molnar, linux-kernel, Masami Hiramatsu On Wed, Feb 23, 2022 at 8:55 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > On Wed, 23 Feb 2022 15:47:28 +0000 > Daniel Dao <dqminh@cloudflare.com> wrote: > > > Hi all > > > > We had some panic when trying to profile some function using ftrace's > > function_graph. > > The panic is attached here: > > > > ------------[ cut here ]------------ > > WARNING: CPU: 30 PID: 812411 at arch/x86/kernel/ftrace.c:96 > > ftrace_verify_code+0x37/0x70 > > Modules linked in: xt_hashlimit macvlan ip_set_hash_netport > > xt_length esp4 xfrm_interface xfrm6_tunnel dummy ipip nft_numgen > > nft_ct ip_gre gre xfrm_user xfrm_algo udp_diag inet_diag fou6 > > ip6_tunnel tunnel6 cls_bpf xt_NFLOG xt_statistic lz4 lz4_compress sit > > tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun > > overlay sch_ingress raid0 md_mod essiv dm_crypt trusted asn1_encoder > > tee dm_mod dax nfnetlink_log nft_log nft_limit nft_counter nf_tables > > ip6table_filter ip6table_mangle ip6table_raw ip6table_security > > ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter > > xt_TCPMSS xt_bpf xt_u32 xt_mark xt_connmark xt_conntrack > > iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment > > xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set > > nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 > > 8021q garp stp mrp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm > > irqbypass crc32_pclmul crc32c_intel aesni_intel > > rapl intel_cstate ipmi_ssif mlx5_core i2c_i801 mlxfw i2c_smbus > > xhci_pci acpi_ipmi tpm_crb tls intel_uncore ioatdma i2c_core xhci_hcd > > ipmi_si dca tpm_tis ipmi_devintf tpm_tis_core tiny_power_button > > ipmi_msghandler tpm button fuse efivarfs ip_tables x_tables > > bcmcrypt(O) crypto_simd cryptd [last unloaded: zsmalloc] > > CPU: 30 PID: 812411 Comm: bash Tainted: G O > > 5.15.19-cloudflare-2022.2.1 #1 > > Hardware name: Quanta Cloud Technology Inc. QuantaPlex > > T42S-2U/T42S-2U MB (Lewisburg-1G) CLX, BIOS 3B16.Q102 02/19/2020 > > RIP: 0010:ftrace_verify_code+0x37/0x70 > > Code: 83 ec 10 65 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 8d > > 7c 24 03 e8 26 1f 1a 00 48 85 c0 75 33 8b 03 39 44 24 03 74 1d <0f> 0b > > b8 ea ff ff ff 48 8b 4c 24 08 65 48 2b 0c 25 28 00 00 00 75 > > RSP: 0018:ffffa86ce19e3d28 EFLAGS: 00010212 > > RAX: 0000000000441f0f RBX: ffffffffa9001e8a RCX: 0000000000000010 > > RDX: 000000000db62b18 RSI: 0000000000000005 RDI: ffffffffa89ea1d0 > > RBP: ffffffffaa764350 R08: 0000000000000001 R09: 0000000000000000 > > R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000001 > > R13: ffff8fb8c00f95f0 R14: 0000000000000000 R15: 000000000000000f > > FS: 00007f3715044740(0000) GS:ffff8ff7bf380000(0000) knlGS:0000000000000000 > > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > > CR2: 000055c306a30298 CR3: 0000002e01756002 CR4: 00000000007706e0 > > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > > PKRU: 55555554 > > Call Trace: > > <TASK> > > ftrace_replace_code+0x9a/0x160 > > ? arch_unoptimize_kprobes+0xb0/0xb0 > > ftrace_modify_all_code+0xbd/0x150 > > ftrace_run_update_code+0x13/0x70 > > ftrace_startup.part.0+0xe1/0x140 > > register_ftrace_graph+0x292/0x2d0 > > graph_trace_init+0x27/0x50 > > tracing_set_tracer+0xdb/0x170 > > tracing_set_trace_write+0x95/0xe0 > > vfs_write+0xbd/0x270 > > ksys_write+0x5f/0xe0 > > do_syscall_64+0x38/0x90 > > entry_SYSCALL_64_after_hwframe+0x44/0xae > > RIP: 0033:0x7f3715135f33 > > Code: 8b 15 61 ef 0c 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f > > 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d > > 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 48 89 54 24 18 > > RSP: 002b:00007ffc4232a038 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 > > RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f3715135f33 > > RDX: 000000000000000f RSI: 000055c2f4c63480 RDI: 0000000000000001 > > RBP: 000055c2f4c63480 R08: 000000000000000a R09: 000000000000000e > > R10: 000055c2f4c66cd0 R11: 0000000000000246 R12: 000000000000000f > > R13: 00007f37152066a0 R14: 000000000000000f R15: 00007f37152068a0 > > </TASK> > > ---[ end trace 3c0096669fc25320 ]--- > > ------------[ ftrace bug ]------------ > > ftrace failed to modify > > [<ffffffffa89ea1d0>] bpf_dispatcher_xdp_func+0x0/0x10 > > Of course this is bpf :-/ > > OK, I found the creation of bpf_dispatcher_xdp_func in include/linux/bpf.h: > > #define DEFINE_BPF_DISPATCHER(name) \ > noinline __nocfi unsigned int bpf_dispatcher_##name##_func( \ > const void *ctx, \ > const struct bpf_insn *insnsi, \ > unsigned int (*bpf_func)(const void *, \ > const struct bpf_insn *)) \ > { \ > return bpf_func(ctx, insnsi); \ > } \ > > You can try changing that to: > > noinline __nocfi notrace unsigned int bpf_dispatcher_##name##_func( \ > > and see if that fixes it for you. > > If you can not change the running kernel, you can try this first: > > # echo 'bpf_dispatcher_*_func' > /sys/kernel/tracing/set_ftrace_notrace > > It doesn't explain the bug, but at least may be a workaround for you. I tried this and it still failed: root@foo:~# echo 'bpf_dispatcher_*_func' > /sys/kernel/tracing/set_ftrace_notrace root@foo:~# trace-cmd record -p function_graph -l handle_mm_fault -P 3367417 plugin 'function_graph' Hit Ctrl^C to stop recording ^CCPU0 data recorded at offset=0x59d000 0 bytes in size CPU1 data recorded at offset=0x59d000 0 bytes in size CPU2 data recorded at offset=0x59d000 0 bytes in size ... 0 bytes in size CPU94 data recorded at offset=0x59d000 0 bytes in size CPU95 data recorded at offset=0x59d000 0 bytes in size /sys/kernel/tracing/set_ftrace_notrace: No such device trace-cmd: No such device opening to '/sys/kernel/tracing/set_graph_function' The failure looks identical to me: [1459708.617487] ------------[ cut here ]------------ [1459708.631682] WARNING: CPU: 80 PID: 2658120 at arch/x86/kernel/ftrace.c:96 ftrace_verify_code+0x37/0x70 [1459708.631702] Modules linked in: mptcp_diag raw_diag unix_diag xt_LOG nf_log_syslog xt_hashlimit esp4 ip_set_hash_netport xt_length mpls_gso mpls_iptunnel mpls_router dummy ipip xfrm_interface xfrm6_tunnel nft_numgen nft_ct ip_gre gre xfrm_user xfrm_algo cls_bpf fou6 ip6_tunnel tunnel6 zstd zstd_compress zram zsmalloc sit tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun tcp_diag overlay sch_ingress udp_diag inet_diag raid0 md_mod essiv dm_crypt trusted tee asn1_encoder dm_mod dax nft_log nft_limit nft_counter nf_tables ip6table_filter ip6table_mangle ip6table_raw ip6table_security ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter xt_TCPMSS xt_bpf xt_NFLOG nfnetlink_log xt_connbytes xt_statistic xt_u32 xt_mark xt_connmark xt_conntrack iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 [1459708.632094] 8021q mrp garp stp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul crc32c_intel aesni_intel rapl intel_cstate ipmi_ssif mlx5_core acpi_ipmi i2c_i801 tpm_crb xhci_pci intel_uncore tls i2c_smbus ipmi_si ioatdma mlxfw xhci_hcd i2c_core ipmi_devintf tpm_tis dca tpm_tis_core ipmi_msghandler tiny_power_button tpm button fuse efivarfs ip_tables x_tables bcmcrypt(O) crypto_simd cryptd [last unloaded: kheaders] [1459708.632292] CPU: 80 PID: 2658120 Comm: trace-cmd Kdump: loaded Tainted: G O 5.15.46-cloudflare-2022.6.2 #1 [1459708.632308] RIP: 0010:ftrace_verify_code+0x37/0x70 [1459708.632318] Code: 83 ec 10 65 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 8d 7c 24 03 e8 56 23 1a 00 48 85 c0 75 33 8b 03 39 44 24 03 74 1d <0f> 0b b8 ea ff ff ff 48 8b 54 24 08 65 48 2b 14 25 28 00 00 00 75 [1459708.632324] RSP: 0018:ffff96d4e1b1fde0 EFLAGS: 00010292 [1459708.632333] RAX: 0000000000441f0f RBX: ffffffffaca01f2a RCX: 0000000000000010 [1459709.019133] RDX: 00007fffffffffff RSI: 0000000000000005 RDI: ffffffffac3ea960 [1459709.019142] RBP: ffffffffae15c310 R08: 0000000000000001 R09: 0000000000000000 [1459709.019147] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000001 [1459709.067594] R13: ffff9232000f9010 R14: ffffffffaca1aa20 R15: ffff923528af8040 [1459709.067603] FS: 00007f503619f740(0000) GS:ffff9270ffa00000(0000) knlGS:0000000000000000 [1459709.067609] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [1459709.067614] CR2: 00007f867b659740 CR3: 00000001e940a004 CR4: 00000000007706e0 [1459709.067619] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [1459709.145561] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [1459709.145566] PKRU: 55555554 [1459709.145570] Call Trace: [1459709.145575] <TASK> [1459709.192099] ftrace_replace_code+0x9a/0x160 [1459709.203969] ftrace_modify_all_code+0xb8/0x150 [1459709.203995] ftrace_run_update_code+0x13/0x70 [1459709.204007] ftrace_hash_move_and_update_ops+0x1af/0x1f0 [1459709.204029] ftrace_regex_release+0x7d/0x150 [1459709.204046] __fput+0x89/0x240 [1459709.204068] task_work_run+0x59/0x90 [1459709.204083] exit_to_user_mode_prepare+0x111/0x120 [1459709.204102] syscall_exit_to_user_mode+0x1d/0x40 [1459709.204117] do_syscall_64+0x48/0x90 [1459709.204130] entry_SYSCALL_64_after_hwframe+0x44/0xae [1459709.204140] RIP: 0033:0x7f50363800f3 [1459709.204161] Code: 8b 15 d9 9e 00 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 03 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 45 c3 0f 1f 40 00 48 83 ec 18 89 7c 24 0c e8 [1459709.204169] RSP: 002b:00007fffe51a87e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003 [1459709.204179] RAX: 0000000000000000 RBX: 000055d469c41c8a RCX: 00007f50363800f3 [1459709.204185] RDX: 0000000000000201 RSI: 000055d46b294420 RDI: 0000000000000004 [1459709.204190] RBP: 000055d46b294420 R08: 0000000000000001 R09: 0000000000000026 [1459709.204195] R10: 0000000000000000 R11: 0000000000000246 R12: 00007fffe51aa8d0 [1459709.204201] R13: 000055d469c5a720 R14: 00007fffe51aa8e0 R15: 000055d469c5a720 [1459709.204242] </TASK> [1459709.204247] ---[ end trace 630569145d18772d ]--- [1459709.204253] ------------[ ftrace bug ]------------ [1459709.204257] ftrace failed to modify [1459709.204262] [<ffffffffac3ea960>] bpf_dispatcher_xdp_func+0x0/0x10 [1459709.204275] actual: ffffffe9:ffffff9b:76:ffffffb0:14 [1459709.204302] Setting ftrace call site to call ftrace function [1459709.204305] ftrace record flags: 10000001 [1459709.204309] (1) expected tramp: ffffffffabc4bcb0 [1459709.204325] ------------[ cut here ]------------ [1459709.204328] WARNING: CPU: 80 PID: 2658120 at kernel/trace/ftrace.c:2073 ftrace_bug+0x22c/0x252 [1459709.204343] Modules linked in: mptcp_diag raw_diag unix_diag xt_LOG nf_log_syslog xt_hashlimit esp4 ip_set_hash_netport xt_length mpls_gso mpls_iptunnel mpls_router dummy ipip xfrm_interface xfrm6_tunnel nft_numgen nft_ct ip_gre gre xfrm_user xfrm_algo cls_bpf fou6 ip6_tunnel tunnel6 zstd zstd_compress zram zsmalloc sit tunnel4 fou ip_tunnel ip6_udp_tunnel udp_tunnel nft_compat veth tun tcp_diag overlay sch_ingress udp_diag inet_diag raid0 md_mod essiv dm_crypt trusted tee asn1_encoder dm_mod dax nft_log nft_limit nft_counter nf_tables ip6table_filter ip6table_mangle ip6table_raw ip6table_security ip6table_nat ip6_tables xt_state xt_multiport xt_tcpmss iptable_filter xt_TCPMSS xt_bpf xt_NFLOG nfnetlink_log xt_connbytes xt_statistic xt_u32 xt_mark xt_connmark xt_conntrack iptable_mangle xt_nat iptable_nat nf_nat xt_owner xt_set xt_comment xt_tcpudp xt_CT iptable_raw ip_set_hash_net ip_set_hash_ip ip_set nfnetlink sch_fq tcp_bbr nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 [1459709.556275] 8021q mrp garp stp llc skx_edac x86_pkg_temp_thermal kvm_intel kvm irqbypass crc32_pclmul crc32c_intel aesni_intel rapl intel_cstate ipmi_ssif mlx5_core acpi_ipmi i2c_i801 tpm_crb xhci_pci intel_uncore tls i2c_smbus ipmi_si ioatdma mlxfw xhci_hcd i2c_core ipmi_devintf tpm_tis dca tpm_tis_core ipmi_msghandler tiny_power_button tpm button fuse efivarfs ip_tables x_tables bcmcrypt(O) crypto_simd cryptd [last unloaded: kheaders] [1459709.556461] CPU: 80 PID: 2658120 Comm: trace-cmd Kdump: loaded Tainted: G W O 5.15.46-cloudflare-2022.6.2 #1 [1459709.556473] RIP: 0010:ftrace_bug+0x22c/0x252 [1459709.556489] Code: ff 84 c0 74 d0 eb b4 48 c7 c7 e2 d5 26 ad e8 83 c9 ff ff 48 89 ef e8 3d 6b 7b ff 48 c7 c7 2a 3d 26 ad 48 89 c6 e8 6c c9 ff ff <0f> 0b c7 05 5a 60 4d 01 01 00 00 00 5b c7 05 5f 60 4d 01 00 00 00 [1459709.556495] RSP: 0018:ffff96d4e1b1fe08 EFLAGS: 00010246 [1459709.556503] RAX: 0000000000000022 RBX: 00000000ffffffea RCX: 0000000000000027 [1459709.556508] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff9270ffa1f770 [1459709.556512] RBP: ffff9232000f9010 R08: ffffffffae1110e0 R09: 000000000000000f [1459709.556517] R10: 000000000000000f R11: ffff92717ffae5b2 R12: ffffffffac3ea960 [1459709.556521] R13: ffff923528af8040 R14: ffffffffaca1aa20 R15: ffff923528af8040 [1459709.556526] FS: 00007f503619f740(0000) GS:ffff9270ffa00000(0000) knlGS:0000000000000000 [1459709.556531] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [1459709.556535] CR2: 00007f867b659740 CR3: 00000001e940a004 CR4: 00000000007706e0 [1459709.556540] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [1459709.556545] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [1459709.556551] PKRU: 55555554 [1459709.556555] Call Trace: [1459709.556561] <TASK> [1459709.556573] ftrace_modify_all_code+0xb8/0x150 [1459709.556591] ftrace_run_update_code+0x13/0x70 [1459709.556600] ftrace_hash_move_and_update_ops+0x1af/0x1f0 [1459709.556621] ftrace_regex_release+0x7d/0x150 [1459709.556637] __fput+0x89/0x240 [1459709.556696] task_work_run+0x59/0x90 [1459709.556712] exit_to_user_mode_prepare+0x111/0x120 [1459709.556729] syscall_exit_to_user_mode+0x1d/0x40 [1459709.556743] do_syscall_64+0x48/0x90 [1459709.556755] entry_SYSCALL_64_after_hwframe+0x44/0xae [1459709.556764] RIP: 0033:0x7f50363800f3 [1459709.556786] Code: 8b 15 d9 9e 00 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 03 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 45 c3 0f 1f 40 00 48 83 ec 18 89 7c 24 0c e8 [1459709.556792] RSP: 002b:00007fffe51a87e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003 [1459709.556801] RAX: 0000000000000000 RBX: 000055d469c41c8a RCX: 00007f50363800f3 [1459709.556806] RDX: 0000000000000201 RSI: 000055d46b294420 RDI: 0000000000000004 [1459709.556812] RBP: 000055d46b294420 R08: 0000000000000001 R09: 0000000000000026 [1459709.556817] R10: 0000000000000000 R11: 0000000000000246 R12: 00007fffe51aa8d0 [1459709.556822] R13: 000055d469c5a720 R14: 00007fffe51aa8e0 R15: 000055d469c5a720 [1459709.556857] </TASK> [1459709.556861] ---[ end trace 630569145d18772e ]--- ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 5.15 ftrace bug when enabling function_graph 2022-08-05 18:37 ` Ivan Babrou @ 2022-08-05 18:53 ` Steven Rostedt 2022-08-05 20:14 ` Ivan Babrou 0 siblings, 1 reply; 7+ messages in thread From: Steven Rostedt @ 2022-08-05 18:53 UTC (permalink / raw) To: Ivan Babrou Cc: Daniel Dao, kernel-team, Ingo Molnar, linux-kernel, Masami Hiramatsu On Fri, 5 Aug 2022 11:37:56 -0700 Ivan Babrou <ivan@cloudflare.com> wrote: > root@foo:~# echo 'bpf_dispatcher_*_func' > > /sys/kernel/tracing/set_ftrace_notrace > > root@foo:~# trace-cmd record -p function_graph -l handle_mm_fault -P 3367417 > plugin 'function_graph' > Hit Ctrl^C to stop recording > [1459709.204253] ------------[ ftrace bug ]------------ > [1459709.204257] ftrace failed to modify > [1459709.204262] [<ffffffffac3ea960>] bpf_dispatcher_xdp_func+0x0/0x10 > [1459709.204275] actual: ffffffe9:ffffff9b:76:ffffffb0:14 > [1459709.204302] Setting ftrace call site to call ftrace function > [1459709.204305] ftrace record flags: 10000001 > [1459709.204309] (1) > expected tramp: ffffffffabc4bcb0 > [1459709.204325] ------------[ cut here ]------------ Did you reboot since the error happened? Because the command you showed should not have touched bpf_dispatcher_xdp_func. -- Steve ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 5.15 ftrace bug when enabling function_graph 2022-08-05 18:53 ` Steven Rostedt @ 2022-08-05 20:14 ` Ivan Babrou 2022-08-05 22:25 ` Steven Rostedt 0 siblings, 1 reply; 7+ messages in thread From: Ivan Babrou @ 2022-08-05 20:14 UTC (permalink / raw) To: Steven Rostedt Cc: Daniel Dao, kernel-team, Ingo Molnar, linux-kernel, Masami Hiramatsu On Fri, Aug 5, 2022 at 11:53 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > On Fri, 5 Aug 2022 11:37:56 -0700 > Ivan Babrou <ivan@cloudflare.com> wrote: > > > root@foo:~# echo 'bpf_dispatcher_*_func' > > > /sys/kernel/tracing/set_ftrace_notrace > > > > root@foo:~# trace-cmd record -p function_graph -l handle_mm_fault -P 3367417 > > plugin 'function_graph' > > Hit Ctrl^C to stop recording > > > > [1459709.204253] ------------[ ftrace bug ]------------ > > [1459709.204257] ftrace failed to modify > > [1459709.204262] [<ffffffffac3ea960>] bpf_dispatcher_xdp_func+0x0/0x10 > > [1459709.204275] actual: ffffffe9:ffffff9b:76:ffffffb0:14 > > [1459709.204302] Setting ftrace call site to call ftrace function > > [1459709.204305] ftrace record flags: 10000001 > > [1459709.204309] (1) > > expected tramp: ffffffffabc4bcb0 > > [1459709.204325] ------------[ cut here ]------------ > > Did you reboot since the error happened? Because the command you showed > should not have touched bpf_dispatcher_xdp_func. I did reboot, but I can reproduce if you have things for me to try. ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 5.15 ftrace bug when enabling function_graph 2022-08-05 20:14 ` Ivan Babrou @ 2022-08-05 22:25 ` Steven Rostedt 2022-08-12 19:03 ` Ivan Babrou 0 siblings, 1 reply; 7+ messages in thread From: Steven Rostedt @ 2022-08-05 22:25 UTC (permalink / raw) To: Ivan Babrou Cc: Daniel Dao, kernel-team, Ingo Molnar, linux-kernel, Masami Hiramatsu On Fri, 5 Aug 2022 13:14:47 -0700 Ivan Babrou <ivan@cloudflare.com> wrote: > On Fri, Aug 5, 2022 at 11:53 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > > > On Fri, 5 Aug 2022 11:37:56 -0700 > > Ivan Babrou <ivan@cloudflare.com> wrote: > > > > > root@foo:~# echo 'bpf_dispatcher_*_func' > > > > /sys/kernel/tracing/set_ftrace_notrace > > > > > > root@foo:~# trace-cmd record -p function_graph -l handle_mm_fault -P 3367417 > > > plugin 'function_graph' > > > Hit Ctrl^C to stop recording > > > > > > > [1459709.204253] ------------[ ftrace bug ]------------ > > > [1459709.204257] ftrace failed to modify > > > [1459709.204262] [<ffffffffac3ea960>] bpf_dispatcher_xdp_func+0x0/0x10 > > > [1459709.204275] actual: ffffffe9:ffffff9b:76:ffffffb0:14 > > > [1459709.204302] Setting ftrace call site to call ftrace function > > > [1459709.204305] ftrace record flags: 10000001 > > > [1459709.204309] (1) > > > expected tramp: ffffffffabc4bcb0 > > > [1459709.204325] ------------[ cut here ]------------ > > > > Did you reboot since the error happened? Because the command you showed > > should not have touched bpf_dispatcher_xdp_func. > > I did reboot, but I can reproduce if you have things for me to try. Let's see if this works manually. Reboot again. Make sure the above "ftrace bug" is not there. If not already mounted, as root: # mount -t tracefs tracefs /sys/krenel/tracing # cd /sys/kernel/tracing # cat enabled_functions Let me know what is there. # echo handle_mm_fault > set_ftrace_filter # cat set_ftrace_filter to make sure that handle_mm_fault is listed. # echo function_graph > current_tracer If it fails again, let me know. It should not, but if it does, it needs to be investigated. Oh, and what exactly is this kernel version. The backtrace you posted shows: 5.15.19-cloudflare-2022.2.1 If you can not reproduce this on a vanilla 5.15.19 kernel, then it may be a bad backport of some patch. -- Steve ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: 5.15 ftrace bug when enabling function_graph 2022-08-05 22:25 ` Steven Rostedt @ 2022-08-12 19:03 ` Ivan Babrou 0 siblings, 0 replies; 7+ messages in thread From: Ivan Babrou @ 2022-08-12 19:03 UTC (permalink / raw) To: Steven Rostedt Cc: Daniel Dao, kernel-team, Ingo Molnar, linux-kernel, Masami Hiramatsu On Fri, Aug 5, 2022 at 3:25 PM Steven Rostedt <rostedt@goodmis.org> wrote: > > On Fri, 5 Aug 2022 13:14:47 -0700 > Ivan Babrou <ivan@cloudflare.com> wrote: > > > On Fri, Aug 5, 2022 at 11:53 AM Steven Rostedt <rostedt@goodmis.org> wrote: > > > > > > On Fri, 5 Aug 2022 11:37:56 -0700 > > > Ivan Babrou <ivan@cloudflare.com> wrote: > > > > > > > root@foo:~# echo 'bpf_dispatcher_*_func' > > > > > /sys/kernel/tracing/set_ftrace_notrace > > > > > > > > root@foo:~# trace-cmd record -p function_graph -l handle_mm_fault -P 3367417 > > > > plugin 'function_graph' > > > > Hit Ctrl^C to stop recording > > > > > > > > > > [1459709.204253] ------------[ ftrace bug ]------------ > > > > [1459709.204257] ftrace failed to modify > > > > [1459709.204262] [<ffffffffac3ea960>] bpf_dispatcher_xdp_func+0x0/0x10 > > > > [1459709.204275] actual: ffffffe9:ffffff9b:76:ffffffb0:14 > > > > [1459709.204302] Setting ftrace call site to call ftrace function > > > > [1459709.204305] ftrace record flags: 10000001 > > > > [1459709.204309] (1) > > > > expected tramp: ffffffffabc4bcb0 > > > > [1459709.204325] ------------[ cut here ]------------ > > > > > > Did you reboot since the error happened? Because the command you showed > > > should not have touched bpf_dispatcher_xdp_func. > > > > I did reboot, but I can reproduce if you have things for me to try. > > Let's see if this works manually. > > Reboot again. > > Make sure the above "ftrace bug" is not there. > > If not already mounted, as root: > > # mount -t tracefs tracefs /sys/krenel/tracing > # cd /sys/kernel/tracing > # cat enabled_functions > > Let me know what is there. > > # echo handle_mm_fault > set_ftrace_filter > # cat set_ftrace_filter > > to make sure that handle_mm_fault is listed. > > # echo function_graph > current_tracer > > If it fails again, let me know. It should not, but if it does, it needs to > be investigated. It does not fail this way. It also doesn't fail when I run perf: perf ftrace -N 'bpf_dispatcher_*_func' -G handle_mm_fault -a -- sleep 1 It does fail without "-N 'bpf_dispatcher_*_func'". I suppose there's something about trace-cmd that makes it fail for me. ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2022-08-12 19:03 UTC | newest] Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2022-02-23 15:47 5.15 ftrace bug when enabling function_graph Daniel Dao 2022-02-23 16:54 ` Steven Rostedt 2022-08-05 18:37 ` Ivan Babrou 2022-08-05 18:53 ` Steven Rostedt 2022-08-05 20:14 ` Ivan Babrou 2022-08-05 22:25 ` Steven Rostedt 2022-08-12 19:03 ` Ivan Babrou
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).