Re: [PATCH net-next] udp: Add tracepoints to monitor skbs going in and out of a UDP socket

[David Howells <dhowells@redhat.com>]

Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:

> I don't quite see what value this tracepoint adds.  Just use kprobe in the
> same spot?  Or tcpdump?

The point was to measure the elapsed time between a packet being received in
the r8169 driver (see the patch I posted for that), getting into udp driver,
being queued by the udp driver and and thence being passed to the af_rxrpc
driver's data_ready function.  You cannot measure this with tcpdump.

Further, packets were crossing each other, so the skb pointer had to be
included so that non-consecutive trace lines could be correlated.  Note that I
have seen up to 4s of delay between a packet being received in r8169 and
arriving in af_rxrpc, so the correlation is necessary.

As for kprobes: spots, plural.  Using kprobes involves installing breakpoint
instructions and taking traps and would seem to require using printk for the
output, which would affect the timings and potentially affect the situation,
especially given the sheer amount of traces produced.  Note that one of these
was in an interrupt handler, which is possibly not the best place to be taking
an illegal instruction trap.

Using kprobes gets worse too.  In my case, the source code and the build tree
aren't on the test machine, which I understand would be a requirement - and
they change regularly (every few minutes).  I boot a monolithic kernel by PXE
directly out of the build tree rather than messing about with building kernel
packages.

Further, I already have tracepoints in rxrpc that produce what I needed that I
could just turn on.

> How was it useful for you?

I could get traces like the following:

<idle>-0     [001] d.h2    95.751176: net_rtl8169_interrupt: enp3s0 st=1
<idle>-0     [001] ..s2    95.751181: net_rtl8169_poll: enp3s0 st=1
<idle>-0     [001] ..s2    95.751185: net_rtl8169_rx: enp3s0 skb=00000000efddbee8
<idle>-0     [001] ..s4    95.751204: udp_rcv: skb=00000000efddbee8
<idle>-0     [001] ..s4    95.751207: rxrpc_skb: s=00000000efddbee8 Rx RCV u=1 m=1 p=rxrpc_rcv_enqueue_skb+0xae/0x18f8
<idle>-0     [001] ..s4    95.751208: rxrpc_rx_packet: 911beb59:b241ccb4:00000006:0001 0000000e 00000001 01 04 DATA
<idle>-0     [001] ..s5    95.751214: rxrpc_skb: s=00000000efddbee8 Rx GOT u=1 m=2 p=rxrpc_input_data+0x557/0x96f
<idle>-0     [001] .Ns4    95.751234: rxrpc_skb: s=00000000efddbee8 Rx FRE u=2 m=1 p=rxrpc_rcv_enqueue_skb+0x15b0/0x18f8
    ls-3183  [001] ...1    95.751252: rxrpc_skb: s=00000000efddbee8 Rx SEE u=1 m=1 p=rxrpc_recvmsg_data.isra.0+0x1bf/0xdc1
    ls-3183  [001] ...1    95.751255: rxrpc_skb: s=00000000efddbee8 Rx ROT u=1 m=1 p=rxrpc_recvmsg_data.isra.0+0x7eb/0xdc1
    ls-3183  [001] ...1    95.751255: rxrpc_skb: s=00000000efddbee8 Rx FRE u=1 m=0 p=rxrpc_recvmsg_data.isra.0+0x840/0xdc1

I can see the interrupt where the NIC pokes the machine to say that there's a
packet, and then I can see the path that the received skbuff passes through
the r8169, udp and af_rxrpc drivers.

For its warts, tracepoints are pretty nice for this sort of thing - but they
have to already exist for you to make use of them, and changing them does
require a recompile.  The main problem I have with tracepoints is during boot,
module load or module removal where the buffer never becomes accessible or
gets wiped.

So, in and of themselves, the udp tracepoints in my patch aren't that useful -
but in combination with tracepoints in the nic driver and in the kernel
service that's using udp, they're actually quite useful.

> and why it couldn't have been achieved by other means?

It probably could, but why should I?

I'm changing my test kernel at very regular intervals.  Stacking on extra
patches to add more tracepoints is much less of an inconvenience than trying
to use kprobes.

David