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
On Wed, 23 Feb 2022 15:47:28 +0000
Daniel Dao <[email protected]> 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
On Wed, Feb 23, 2022 at 8:55 AM Steven Rostedt <[email protected]> wrote:
>
> On Wed, 23 Feb 2022 15:47:28 +0000
> Daniel Dao <[email protected]> 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 ]---
On Fri, 5 Aug 2022 11:37:56 -0700
Ivan Babrou <[email protected]> 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
On Fri, Aug 5, 2022 at 11:53 AM Steven Rostedt <[email protected]> wrote:
>
> On Fri, 5 Aug 2022 11:37:56 -0700
> Ivan Babrou <[email protected]> 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.
On Fri, 5 Aug 2022 13:14:47 -0700
Ivan Babrou <[email protected]> wrote:
> On Fri, Aug 5, 2022 at 11:53 AM Steven Rostedt <[email protected]> wrote:
> >
> > On Fri, 5 Aug 2022 11:37:56 -0700
> > Ivan Babrou <[email protected]> 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
On Fri, Aug 5, 2022 at 3:25 PM Steven Rostedt <[email protected]> wrote:
>
> On Fri, 5 Aug 2022 13:14:47 -0700
> Ivan Babrou <[email protected]> wrote:
>
> > On Fri, Aug 5, 2022 at 11:53 AM Steven Rostedt <[email protected]> wrote:
> > >
> > > On Fri, 5 Aug 2022 11:37:56 -0700
> > > Ivan Babrou <[email protected]> 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.