selftests/bpf: xdp_hw_metadata track more timestamps

To correlate the hardware RX timestamp with something, add tracking of
two software timestamps both clock source CLOCK_TAI (see description in
man clock_gettime(2)).

XDP metadata is extended with xdp_timestamp for capturing when XDP
received the packet. Populated with BPF helper bpf_ktime_get_tai_ns(). I
could not find a BPF helper for getting CLOCK_REALTIME, which would have
been preferred. In userspace when AF_XDP sees the packet another
software timestamp is recorded via clock_gettime() also clock source
CLOCK_TAI.

Example output shortly after loading igc driver:

  poll: 1 (0) skip=1 fail=0 redir=2
  xsk_ring_cons__peek: 1
  0x12557a8: rx_desc[1]->addr=100000000009000 addr=9100 comp_addr=9000
  rx_hash: 0x82A96531 with RSS type:0x1
  rx_timestamp:  1681740540304898909 (sec:1681740540.3049)
  XDP RX-time:   1681740577304958316 (sec:1681740577.3050) delta sec:37.0001 (37000059.407 usec)
  AF_XDP time:   1681740577305051315 (sec:1681740577.3051) delta sec:0.0001 (92.999 usec)
  0x12557a8: complete idx=9 addr=9000

The first observation is that the 37 sec difference between RX HW vs XDP
timestamps, which indicate hardware is likely clock source
CLOCK_REALTIME, because (as of this writing) CLOCK_TAI is initialised
with a 37 sec offset.

The 93 usec (microsec) difference between XDP vs AF_XDP userspace is the
userspace wakeup time. On this hardware it was caused by CPU idle sleep
states, which can be reduced by tuning /dev/cpu_dma_latency.

View current requested/allowed latency bound via:
  hexdump --format '"%d\n"' /dev/cpu_dma_latency

More explanation of the output and how this can be used to identify
clock drift for the HW clock can be seen here[1]:

[1] https://github.com/xdp-project/xdp-project/blob/master/areas/hints/xdp_hints_kfuncs02_driver_igc.org

Signed-off-by: Jesper Dangaard Brouer <brouer@redhat.com>
Signed-off-by: Daniel Borkmann <daniel@iogearbox.net>
Acked-by: Stanislav Fomichev <sdf@google.com>
Acked-by: Song Yoong Siang <yoong.siang.song@intel.com>
Link: https://lore.kernel.org/bpf/168182466298.616355.2544377890818617459.stgit@firesoul

diff --git a/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c b/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
index e1c787815e44bba5a9f1e41d4649f84f16f1510f..b2dfd7066c6e4fdf9ff1016bc263b540306ddd3f 100644 (file)
--- a/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
+++ b/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
@@ -77,7 +77,9 @@ int rx(struct xdp_md *ctx)
        }
 
        err = bpf_xdp_metadata_rx_timestamp(ctx, &meta->rx_timestamp);
-       if (err)
+       if (!err)
+               meta->xdp_timestamp = bpf_ktime_get_tai_ns();
+       else
                meta->rx_timestamp = 0; /* Used by AF_XDP as not avail signal */
 
        err = bpf_xdp_metadata_rx_hash(ctx, &meta->rx_hash, &meta->rx_hash_type);

diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c b/tools/testing/selftests/bpf/xdp_hw_metadata.c
index 987cf0db5ebc80f70b3c62d641bc878ed8ee1805..613321eb84c1901b56350e8db4ae910546fb1117 100644 (file)
--- a/tools/testing/selftests/bpf/xdp_hw_metadata.c
+++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c
@@ -27,6 +27,7 @@
 #include <sys/mman.h>
 #include <net/if.h>
 #include <poll.h>
+#include <time.h>
 
 #include "xdp_metadata.h"
 
@@ -134,18 +135,52 @@ static void refill_rx(struct xsk *xsk, __u64 addr)
        }
 }
 
-static void verify_xdp_metadata(void *data)
+#define NANOSEC_PER_SEC 1000000000 /* 10^9 */
+static __u64 gettime(clockid_t clock_id)
+{
+       struct timespec t;
+       int res;
+
+       /* See man clock_gettime(2) for type of clock_id's */
+       res = clock_gettime(clock_id, &t);
+
+       if (res < 0)
+               error(res, errno, "Error with clock_gettime()");
+
+       return (__u64) t.tv_sec * NANOSEC_PER_SEC + t.tv_nsec;
+}
+
+static void verify_xdp_metadata(void *data, clockid_t clock_id)
 {
        struct xdp_meta *meta;
 
        meta = data - sizeof(*meta);
 
-       printf("rx_timestamp: %llu\n", meta->rx_timestamp);
        if (meta->rx_hash_err < 0)
                printf("No rx_hash err=%d\n", meta->rx_hash_err);
        else
                printf("rx_hash: 0x%X with RSS type:0x%X\n",
                       meta->rx_hash, meta->rx_hash_type);
+
+       printf("rx_timestamp:  %llu (sec:%0.4f)\n", meta->rx_timestamp,
+              (double)meta->rx_timestamp / NANOSEC_PER_SEC);
+       if (meta->rx_timestamp) {
+               __u64 usr_clock = gettime(clock_id);
+               __u64 xdp_clock = meta->xdp_timestamp;
+               __s64 delta_X = xdp_clock - meta->rx_timestamp;
+               __s64 delta_X2U = usr_clock - xdp_clock;
+
+               printf("XDP RX-time:   %llu (sec:%0.4f) delta sec:%0.4f (%0.3f usec)\n",
+                      xdp_clock, (double)xdp_clock / NANOSEC_PER_SEC,
+                      (double)delta_X / NANOSEC_PER_SEC,
+                      (double)delta_X / 1000);
+
+               printf("AF_XDP time:   %llu (sec:%0.4f) delta sec:%0.4f (%0.3f usec)\n",
+                      usr_clock, (double)usr_clock / NANOSEC_PER_SEC,
+                      (double)delta_X2U / NANOSEC_PER_SEC,
+                      (double)delta_X2U / 1000);
+       }
+
 }
 
 static void verify_skb_metadata(int fd)
@@ -193,7 +228,7 @@ static void verify_skb_metadata(int fd)
        printf("skb hwtstamp is not found!\n");
 }
 
-static int verify_metadata(struct xsk *rx_xsk, int rxq, int server_fd)
+static int verify_metadata(struct xsk *rx_xsk, int rxq, int server_fd, clockid_t clock_id)
 {
        const struct xdp_desc *rx_desc;
        struct pollfd fds[rxq + 1];
@@ -243,7 +278,8 @@ static int verify_metadata(struct xsk *rx_xsk, int rxq, int server_fd)
                        addr = xsk_umem__add_offset_to_addr(rx_desc->addr);
                        printf("%p: rx_desc[%u]->addr=%llx addr=%llx comp_addr=%llx\n",
                               xsk, idx, rx_desc->addr, addr, comp_addr);
-                       verify_xdp_metadata(xsk_umem__get_data(xsk->umem_area, addr));
+                       verify_xdp_metadata(xsk_umem__get_data(xsk->umem_area, addr),
+                                           clock_id);
                        xsk_ring_cons__release(&xsk->rx, 1);
                        refill_rx(xsk, comp_addr);
                }
@@ -370,6 +406,7 @@ static void timestamping_enable(int fd, int val)
 
 int main(int argc, char *argv[])
 {
+       clockid_t clock_id = CLOCK_TAI;
        int server_fd = -1;
        int ret;
        int i;
@@ -443,7 +480,7 @@ int main(int argc, char *argv[])
                error(1, -ret, "bpf_xdp_attach");
 
        signal(SIGINT, handle_signal);
-       ret = verify_metadata(rx_xsk, rxq, server_fd);
+       ret = verify_metadata(rx_xsk, rxq, server_fd, clock_id);
        close(server_fd);
        cleanup();
        if (ret)

diff --git a/tools/testing/selftests/bpf/xdp_metadata.h b/tools/testing/selftests/bpf/xdp_metadata.h
index 0c4624dc6f2f719183b21e7e0bd1fbc9e6b72164..938a729bd3072f96dac570d04ab68cb9dcde0379 100644 (file)
--- a/tools/testing/selftests/bpf/xdp_metadata.h
+++ b/tools/testing/selftests/bpf/xdp_metadata.h
@@ -11,6 +11,7 @@
 
 struct xdp_meta {
        __u64 rx_timestamp;
+       __u64 xdp_timestamp;
        __u32 rx_hash;
        union {
                __u32 rx_hash_type;