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.
