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

[Stanislav Fomichev <sdf@google.com>]

On Wed, Jan 25, 2023 at 7:10 AM Jesper Dangaard Brouer
<jbrouer@redhat.com> wrote:
>
>
> 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

Great, thank you for testing and investigating the clock discrepancy!
Will send it as a patch later today, will add your Tested-by (if you
don't mind).

> > 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");
> >
> >
>