lkml.org 
[lkml]   [2022]   [Feb]   [23]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: 5.15 ftrace bug when enabling function_graph
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

\
 
 \ /
  Last update: 2022-02-23 17:56    [W:0.056 / U:0.512 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site