[xdp-hints] Re: [PATCH bpf-next v8 17/17] selftests/bpf: Simple program to dump XDP RX metadata

[Jesper Dangaard Brouer <jbrouer@redhat.com>]

On 24/01/2023 19.48, sdf@google.com wrote:
> On 01/24, Stanislav Fomichev wrote:
>> On Tue, Jan 24, 2023 at 7:26 AM Jesper Dangaard Brouer
>> <jbrouer@redhat.com> wrote:
>> >
>> >
>> > Testing this on mlx5 and I'm not getting the RX-timestamp.
>> > See command details below.
> 
>> CC'ed Toke since I've never tested mlx5 myself.
>> I was pretty close to getting the setup late last week, let me try to
>> see whether it's ready or not.
> 
>> > On 19/01/2023 23.15, Stanislav Fomichev wrote:
>> > > To be used for verification of driver implementations. Note that
>> > > the skb path is gone from the series, but I'm still keeping the
>> > > implementation for any possible future work.
>> > >
>> > > $ xdp_hw_metadata <ifname>
>> >
>> > sudo ./xdp_hw_metadata mlx5p1
>> >
>> > Output:
>> > [...cut ...]
>> > open bpf program...
>> > load bpf program...
>> > prepare skb endpoint...
>> > XXX timestamping_enable(): setsockopt(SO_TIMESTAMPING) ret:0
>> > prepare xsk map...
>> > map[0] = 3
>> > map[1] = 4
>> > map[2] = 5
>> > map[3] = 6
>> > map[4] = 7
>> > map[5] = 8
>> > attach bpf program...
>> > poll: 0 (0)
>> > poll: 0 (0)
>> > poll: 0 (0)
>> > poll: 1 (0)
>> > xsk_ring_cons__peek: 1
>> > 0x1821788: rx_desc[0]->addr=100000000008000 addr=8100 comp_addr=8000
>> > rx_timestamp: 0
>> > rx_hash: 2773355807
>> > 0x1821788: complete idx=8 addr=8000
>> > poll: 0 (0)
>> >
>> > The trace_pipe:
>> >
>> > $ sudo cat /sys/kernel/debug/tracing/trace_pipe
>> >            <idle>-0       [005] ..s2.  2722.884762: bpf_trace_printk:
>> > forwarding UDP:9091 to AF_XDP
>> >            <idle>-0       [005] ..s2.  2722.884771: bpf_trace_printk:
>> > populated rx_hash with 2773355807
>> >
>> >
>> > > On the other machine:
>> > >
>> > > $ echo -n xdp | nc -u -q1 <target> 9091 # for AF_XDP
>> >
>> > Fixing the source-port to see if RX-hash remains the same.
>> >
>> >   $ echo xdp | nc --source-port=2000 --udp 198.18.1.1 9091
>> >
>> > > $ echo -n skb | nc -u -q1 <target> 9092 # for skb
>> > >
>> > > Sample output:
>> > >
>> > >    # xdp
>> > >    xsk_ring_cons__peek: 1
>> > >    0x19f9090: rx_desc[0]->addr=100000000008000 addr=8100 
>> comp_addr=8000
>> > >    rx_timestamp_supported: 1
>> > >    rx_timestamp: 1667850075063948829
>> > >    0x19f9090: complete idx=8 addr=8000
>> >
>> > xsk_ring_cons__peek: 1
>> > 0x1821788: rx_desc[0]->addr=100000000008000 addr=8100 comp_addr=8000
>> > rx_timestamp: 0
>> > rx_hash: 2773355807
>> > 0x1821788: complete idx=8 addr=8000
>> >
>> > It doesn't look like hardware RX-timestamps are getting enabled.
>> >
>> > [... cut to relevant code ...]
>> >
>> > > diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c 
>> b/tools/testing/selftests/bpf/xdp_hw_metadata.c
>> > > new file mode 100644
>> > > index 000000000000..0008f0f239e8
>> > > --- /dev/null
>> > > +++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c
>> > > @@ -0,0 +1,403 @@
>> > [...]
>> >
>> > > +static void timestamping_enable(int fd, int val)
>> > > +{
>> > > +     int ret;
>> > > +
>> > > +     ret = setsockopt(fd, SOL_SOCKET, SO_TIMESTAMPING, &val, 
>> sizeof(val));
>> > > +     if (ret < 0)
>> > > +             error(-1, errno, "setsockopt(SO_TIMESTAMPING)");
>> > > +}
>> > > +
>> > > +int main(int argc, char *argv[])
>> > > +{
>> > [...]
>> >
>> > > +     printf("prepare skb endpoint...\n");
>> > > +     server_fd = start_server(AF_INET6, SOCK_DGRAM, NULL, 9092, 
>> 1000);
>> > > +     if (server_fd < 0)
>> > > +             error(-1, errno, "start_server");
>> > > +     timestamping_enable(server_fd,
>> > > +                         SOF_TIMESTAMPING_SOFTWARE |
>> > > +                         SOF_TIMESTAMPING_RAW_HARDWARE);
>> > > +
>> >
>> > I don't think this timestamping_enable() with these flags are enough to
>> > enable hardware timestamping.
> 
> Yeah, agreed, looks like that's the issue. timestamping_enable() has
> been used for the xdp->skb path that I've eventually removed from the
> series, so it's mostly a noop here..
> 
> Maybe you can try the following before I send a proper patch?

Yes, below patch fixed the issue, thx.

Now I get HW timestamps, plus I added some software CLOCK_TAI timestamps
to compare against.

Output is now:

  poll: 1 (0)
  xsk_ring_cons__peek: 1
  0xf64788: rx_desc[0]->addr=100000000008000 addr=8100 comp_addr=8000
  rx_hash: 3697961069
  rx_timestamp:  1674657672142214773 (sec:1674657672.1422)
  XDP RX-time:   1674657709561774876 (sec:1674657709.5618) delta sec:37.4196
  AF_XDP time:   1674657709561871034 (sec:1674657709.5619) delta 
sec:0.0001 (96.158 usec)
  0xf64788: complete idx=8 addr=8000

My NIC hardware clock is clearly not synced with system time, as above 
delta say 37.4 seconds between HW and XDP timestamps (using 
bpf_ktime_get_tai_ns()).

Time between XDP and AF_XDP wakeup is reported to be 96 usec, which is 
also higher than I expected.  As explained in [1] this is caused by CPU 
sleep states.

My /dev/cpu_dma_latency was set to 2000000000.  Applying tuned-adm 
profile latency-performance this value change to 2.

  $ sudo hexdump --format '"%d\n"' /dev/cpu_dma_latency
  2000000000
  $ sudo hexdump --format '"%d\n"' /dev/cpu_dma_latency
  2

Now the time between XDP and AF_XDP wakeup is reduced to approx 12 usec.

  rx_timestamp:  1674659206344977544 (sec:1674659206.3450)
  XDP RX-time:   1674659243776087765 (sec:1674659243.7761) delta sec:37.4311
  AF_XDP time:   1674659243776099841 (sec:1674659243.7761) delta 
sec:0.0000 (12.076 usec)


[1] 
https://github.com/xdp-project/bpf-examples/tree/master/AF_XDP-interaction

> diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c 
> b/tools/testing/selftests/bpf/xdp_hw_metadata.c
> index 0008f0f239e8..dceddb17fbc9 100644
> --- a/tools/testing/selftests/bpf/xdp_hw_metadata.c
> +++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c
> @@ -24,6 +24,7 @@
>   #include <linux/net_tstamp.h>
>   #include <linux/udp.h>
>   #include <linux/sockios.h>
> +#include <linux/net_tstamp.h>
>   #include <sys/mman.h>
>   #include <net/if.h>
>   #include <poll.h>
> @@ -278,13 +279,37 @@ static int rxq_num(const char *ifname)
> 
>       ret = ioctl(fd, SIOCETHTOOL, &ifr);
>       if (ret < 0)
> -        error(-1, errno, "socket");
> +        error(-1, errno, "ioctl(SIOCETHTOOL)");
> 
>       close(fd);
> 
>       return ch.rx_count + ch.combined_count;
>   }
> 
> +static void hwtstamp_enable(const char *ifname)
> +{
> +    struct hwtstamp_config cfg = {
> +        .rx_filter = HWTSTAMP_FILTER_ALL,
> +
> +    };
> +
> +    struct ifreq ifr = {
> +        .ifr_data = (void *)&cfg,
> +    };
> +    strcpy(ifr.ifr_name, ifname);
> +    int fd, ret;
> +
> +    fd = socket(AF_UNIX, SOCK_DGRAM, 0);
> +    if (fd < 0)
> +        error(-1, errno, "socket");
> +
> +    ret = ioctl(fd, SIOCSHWTSTAMP, &ifr);
> +    if (ret < 0)
> +        error(-1, errno, "ioctl(SIOCSHWTSTAMP)");
> +
> +    close(fd);
> +}
> +
>   static void cleanup(void)
>   {
>       LIBBPF_OPTS(bpf_xdp_attach_opts, opts);
> @@ -341,6 +366,8 @@ int main(int argc, char *argv[])
> 
>       printf("rxq: %d\n", rxq);
> 
> +    hwtstamp_enable(ifname);
> +
>       rx_xsk = malloc(sizeof(struct xsk) * rxq);
>       if (!rx_xsk)
>           error(-1, ENOMEM, "malloc");
> 
>