Re: bpf: missed fentry/fexit invocations due to implicit recursion

[Jiri Olsa <olsajiri@gmail.com>]

On Tue, Mar 21, 2023 at 06:13:29PM +0100, Davide Miola wrote:
> Hello,
> 
> I've been trying to measure the per-task CPU time spent in the kernel
> function ip_queue_xmit by attaching an entry and exit probe to said
> function in the form of fentry/fexit programs, but I've noticed that
> under heavy traffic conditions this solution breaks. I first observed
> this as the exit program was occasionally being called more times
> than the entry, which of course shouldn't be possible.
> 
> Below is the stack trace (most recent call last) of one such event:
> 
> 0xffffffffb8800099 entry_SYSCALL_64_after_hwframe
> 0xffffffffb879fb49 do_syscall_64
> 0xffffffffb7d8ff49 __x64_sys_read
> 0xffffffffb7d8fef5 ksys_read
> 0xffffffffb7d8d3d3 vfs_read
> 0xffffffffb7d8caae new_sync_read
> 0xffffffffb84c0f1f sock_read_iter
> 0xffffffffb84c0e81 sock_recvmsg
> 0xffffffffb85ef8bc inet_recvmsg
> 0xffffffffb85b13f4 tcp_recvmsg
> 0xffffffffb84ca5b0 release_sock
> 0xffffffffb84ca535 __release_sock
> 0xffffffffb85ce0a7 tcp_v4_do_rcv
> 0xffffffffb85bfd2a tcp_rcv_established
> 0xffffffffb85b5d32 __tcp_ack_snd_check
> 0xffffffffb85c8dcc tcp_send_ack
> 0xffffffffb85c5d0f __tcp_send_ack.part.0
> 0xffffffffb85a0e75 ip_queue_xmit
> 0xffffffffc0f3b044 rapl_msr_priv        [intel_rapl_msr]
> 0xffffffffc0c769aa bpf_prog_6deef7357e7b4530    [bpf]
> 0xffffffffb7c6707e __htab_map_lookup_elem
> 0xffffffffb7c66fe0 lookup_nulls_elem_raw
> 0xffffffffb8800da7 asm_common_interrupt
> 0xffffffffb87a11ae common_interrupt
> 0xffffffffb7ac57b4 irq_exit_rcu
> 0xffffffffb8a000d6 __softirqentry_text_start
> 0xffffffffb84f1fd6 net_rx_action
> 0xffffffffb84f1bf0 __napi_poll
> 0xffffffffc02af547 i40e_napi_poll       [i40e]
> 0xffffffffb84f1a7a napi_complete_done
> 0xffffffffb84f158e netif_receive_skb_list_internal
> 0xffffffffb84f12ba __netif_receive_skb_list_core
> 0xffffffffb84f04fa __netif_receive_skb_core.constprop.0
> 0xffffffffc079e192 br_handle_frame      [bridge]
> 0xffffffffc03f9ce5 br_nf_pre_routing    [br_netfilter]
> 0xffffffffc03f979c br_nf_pre_routing_finish     [br_netfilter]
> 0xffffffffc03f95db br_nf_hook_thresh    [br_netfilter]
> 0xffffffffc079dc07 br_handle_frame_finish       [bridge]
> 0xffffffffc079da28 br_pass_frame_up     [bridge]
> 0xffffffffb84f2fa3 netif_receive_skb
> 0xffffffffb84f2f15 __netif_receive_skb
> 0xffffffffb84f2eba __netif_receive_skb_one_core
> 0xffffffffb859aefa ip_rcv
> 0xffffffffb858eb61 nf_hook_slow
> 0xffffffffc03f88ec ip_sabotage_in       [br_netfilter]
> 0xffffffffb859ae5e ip_rcv_finish
> 0xffffffffb859ab0b ip_local_deliver
> 0xffffffffb859a9f8 ip_local_deliver_finish
> 0xffffffffb859a79c ip_protocol_deliver_rcu
> 0xffffffffb85d137e tcp_v4_rcv
> 0xffffffffb85ce0a7 tcp_v4_do_rcv
> 0xffffffffb85bf9cb tcp_rcv_established
> 0xffffffffb85c6fe7 __tcp_push_pending_frames
> 0xffffffffb85c6859 tcp_write_xmit
> 0xffffffffb85a0e75 ip_queue_xmit
> 0xffffffffc0f3b090 rapl_msr_priv        [intel_rapl_msr]
> 0xffffffffc00f0fb5 __this_module        [linear]
> 0xffffffffc00f0fb5 __this_module        [linear]
> 
> As I interpret this, it appears that after the first invocation of
> ip_queue_xmit the entry function is called, but it's then interrupted
> by an irq which eventually leads back to ip_queue_xmit, where the
> entry's bpf_prog->active field is still 1, preventing its invocation
> (whereas the exit program can instead be executed).
> Inspecting bpftool seems to confirm this, as I can see an unbalanced,
> slowly increasing recursion_misses counter for both programs.

seems correct to me, can you see see recursion_misses counter in
bpftool prog output for the entry tracing program?

jirka

> 
> I'm not even sure this would qualify as a bug, but - even though I've
> only been able to reproduce this consistently with a 40G
> iperf3 --bidir - the chance of it happening render fentry/fexit
> unreliable for the job.