lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
Open Source and information security mailing list archives
| ||
|
Message-ID: <PH0PR11MB58301E7F051FFB67E2C6B379D8D2A@PH0PR11MB5830.namprd11.prod.outlook.com> Date: Fri, 13 Oct 2023 01:13:55 +0000 From: "Song, Yoong Siang" <yoong.siang.song@...el.com> To: Stanislav Fomichev <sdf@...gle.com>, Jesper Dangaard Brouer <hawk@...nel.org> CC: "bpf@...r.kernel.org" <bpf@...r.kernel.org>, "ast@...nel.org" <ast@...nel.org>, "daniel@...earbox.net" <daniel@...earbox.net>, "andrii@...nel.org" <andrii@...nel.org>, "martin.lau@...ux.dev" <martin.lau@...ux.dev>, "song@...nel.org" <song@...nel.org>, "yhs@...com" <yhs@...com>, "john.fastabend@...il.com" <john.fastabend@...il.com>, "kpsingh@...nel.org" <kpsingh@...nel.org>, "haoluo@...gle.com" <haoluo@...gle.com>, "jolsa@...nel.org" <jolsa@...nel.org>, "kuba@...nel.org" <kuba@...nel.org>, "toke@...nel.org" <toke@...nel.org>, "willemb@...gle.com" <willemb@...gle.com>, "dsahern@...nel.org" <dsahern@...nel.org>, "Karlsson, Magnus" <magnus.karlsson@...el.com>, "bjorn@...nel.org" <bjorn@...nel.org>, "Fijalkowski, Maciej" <maciej.fijalkowski@...el.com>, "netdev@...r.kernel.org" <netdev@...r.kernel.org>, "xdp-hints@...-project.net" <xdp-hints@...-project.net> Subject: RE: [PATCH bpf-next v3 09/10] selftests/bpf: Add TX side to xdp_hw_metadata On Wednesday, October 11, 2023 4:40 AM, Stanislav Fomichev <sdf@...gle.com> wrote: >On 10/09, Stanislav Fomichev wrote: >> On 10/09, Jesper Dangaard Brouer wrote: >> > >> > >> > On 03/10/2023 22.05, Stanislav Fomichev wrote: >> > > When we get a packet on port 9091, we swap src/dst and send it out. >> > > At this point we also request the timestamp and checksum offloads. >> > > >> > > Checksum offload is verified by looking at the tcpdump on the other side. >> > > The tool prints pseudo-header csum and the final one it expects. >> > > The final checksum actually matches the incoming packets checksum >> > > because we only flip the src/dst and don't change the payload. >> > > >> > > Some other related changes: >> > > - switched to zerocopy mode by default; new flag can be used to force >> > > old behavior >> > > - request fixed tx_metadata_len headroom >> > > - some other small fixes (umem size, fill idx+i, etc) >> > > >> > > mvbz3:~# ./xdp_hw_metadata eth3 >> > > ... >> > > 0x1062cb8: rx_desc[0]->addr=80100 addr=80100 comp_addr=80100 >> > > rx_hash: 0x2E1B50B9 with RSS type:0x2A >> > > rx_timestamp: 1691436369532047139 (sec:1691436369.5320) >> > > XDP RX-time: 1691436369261756803 (sec:1691436369.2618) delta sec:- >0.2703 (-270290.336 usec) >> > >> > I guess system time isn't configured to be in sync with NIC HW time, >> > as delta is a negative offset. >> > >> > > AF_XDP time: 1691436369261878839 (sec:1691436369.2619) delta >sec:0.0001 (122.036 usec) >> > The AF_XDP time is also software system time and compared to XDP >> > RX-time, it shows a delta of 122 usec. This number indicate to me >> > that the CPU is likely configured with power saving sleep states. >> >> Yes, I don't do any synchronization and don't disable the sleep states. >> >> > > 0x1062cb8: ping-pong with csum=3b8e (want de7e) csum_start=54 >> > > csum_offset=6 >> > > 0x1062cb8: complete tx idx=0 addr=10 >> > > 0x1062cb8: tx_timestamp: 1691436369598419505 >> > > (sec:1691436369.5984) >> > >> > Could we add something that we can relate tx_timestamp to? >> > >> > Like we do with the other delta calculations, as it helps us to >> > understand/validate if the number we get back is sane. Like negative >> > offset aboves tells us that system time sync isn't configured, and >> > that system have configures C-states. >> > >> > I suggest delta comparing "tx_timestamp" to "rx_timestamp", as they >> > are the same clock domain. It will tell us the total time spend >> > from HW RX to HW TX, counting all the time used by software "ping-pong". >> > >> > 1691436369.5984-1691436369.5320 = 0.0664 sec = 66.4 ms >> > >> > When implementing this, it could be (1) practical to store the >> > "rx_timestamp" in the metadata area of the completion packet, or (2) >> > should we have a mechanism for external storage that can be keyed on >> > the umem "addr"? >> >> Sounds good. I can probably just store last rx_timestamp somewhere in >> the global var and do a delta on tx? Since the test is single threaded >> and sequential, not sure we need the mechanism to pass the tstamp around. >> LMK if you disagree and I'm missing something. > >I ended up reshuffling current code a bit to basically use clock tai as a reference for >every line. Feels like its a bit simpler when everything is referenced against the >same clock? > >For RX part, I rename existing XDP/AF_XDP to HW/SW and dump them both >relative to tai. > >0x195d1f0: rx_desc[0]->addr=80100 addr=80100 comp_addr=80100 >rx_hash: 0xEE2BBD59 with RSS type:0x2A >rx_timestamp: 1696969312125212179 (sec:1696969312.1252) >HW RX-time: 1696969312125212179 (sec:1696969312.1252) to CLOCK_TAI delta >sec:-0.1339 (-133862.968 usec) >SW RX-time: 1696969311991283421 (sec:1696969311.9913) to CLOCK_TAI delta >sec:0.0001 (65.790 usec) >0x195d1f0: ping-pong with csum=3b8e (want de5f) csum_start=54 csum_offset=6 >0x195d1f0: complete tx idx=0 addr=8 >tx_timestamp: 1696969312152959759 (sec:1696969312.1530) >SW RX-time: 1696969311991283421 (sec:1696969311.9913) to CLOCK_TAI delta >sec:0.0101 (10139.862 usec) >HW RX-time: 1696969312125212179 (sec:1696969312.1252) to HW TX- >complete-time delta sec:0.0277 (27747.580 usec) >HW TX-complete-time: 1696969312152959759 (sec:1696969312.1530) to >CLOCK_TAI delta sec:-0.1515 (-151536.476 usec) > >For TX part, I add a bunch of reference points: >1) SW RX-time (meta->xdp_timestamp) vs CLOCK_TAI (aka tai-at-complete-time) >2) HW RX-time (meta->rx_timestamp) vs HW TX-complete-time (new af_xdp >timestamp) >3) HW TX-complete-time vs CLOCK_TAI > >What do you think? See the patch below. Hi Stanislav, For me, the "CLOCK_TAI" in the printing is a bit confusing because 1. There are two value of tai which refer to different moment but having the same name "CLOCK_TAI" 2. SW RX-time is also a clock tai. So, I suggest to change the naming: - HW RX-time: the moment NIC receive the packet (based on PHC) - XDP RX-time: the moment bpf prog parse the packet (based on tai) - SW RX-time: the moment user app receive the packet (based on tai) - HW TX-complete-time: the moment NIC send out the packet (based on PHC) - SW TX-complete-time: the moment user app know the packet being send out (based on tai) Thanks & Regards Siang > >Note: all 3 of the above should, in theory, be more or less constant (with irq >moderation / etc disabled). But for me on mlx5 (2) they are not and looks like hw rx >timestamp jitters a quite a bit. I don't have a clue rigt now on why, will try to take a >separate look, but it's unrelated to the tx side. > > >diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c >b/tools/testing/selftests/bpf/xdp_hw_metadata.c >index ab83d0ba6763..64a90d7479c1 100644 >--- a/tools/testing/selftests/bpf/xdp_hw_metadata.c >+++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c >@@ -57,6 +57,8 @@ const char *ifname; > int ifindex; > int rxq; > bool skip_tx; >+__u64 last_hw_rx_timestamp; >+__u64 last_sw_rx_timestamp; > > void test__fail(void) { /* for network_helpers.c */ } > >@@ -167,6 +169,16 @@ static __u64 gettime(clockid_t clock_id) > return (__u64) t.tv_sec * NANOSEC_PER_SEC + t.tv_nsec; } > >+static void print_tstamp_delta(const char *name, const char *refname, >+__u64 tstamp, __u64 reference) { >+ __s64 delta = (__s64)reference - (__s64)tstamp; >+ >+ printf("%s: %llu (sec:%0.4f) to %s delta sec:%0.4f (%0.3f usec)\n", >+ name, tstamp, (double)tstamp / NANOSEC_PER_SEC, refname, >+ (double)delta / NANOSEC_PER_SEC, >+ (double)delta / 1000); >+} >+ > static void verify_xdp_metadata(void *data, clockid_t clock_id) { > struct xdp_meta *meta; >@@ -182,22 +194,15 @@ static void verify_xdp_metadata(void *data, clockid_t >clock_id) > 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); >- } >+ __u64 ref_tstamp = gettime(clock_id); >+ >+ /* store received timestamps to calculate a delta at tx */ >+ last_hw_rx_timestamp = meta->rx_timestamp; >+ last_sw_rx_timestamp = meta->xdp_timestamp; > >+ print_tstamp_delta("HW RX-time", "CLOCK_TAI", meta- >>rx_timestamp, ref_tstamp); >+ print_tstamp_delta("SW RX-time", "CLOCK_TAI", meta- >>xdp_timestamp, ref_tstamp); >+ } > } > > static void verify_skb_metadata(int fd) @@ -245,7 +250,7 @@ static void >verify_skb_metadata(int fd) > printf("skb hwtstamp is not found!\n"); } > >-static bool complete_tx(struct xsk *xsk) >+static bool complete_tx(struct xsk *xsk, clockid_t clock_id) > { > struct xsk_tx_metadata *meta; > __u64 addr; >@@ -260,9 +265,17 @@ static bool complete_tx(struct xsk *xsk) > meta = data - sizeof(struct xsk_tx_metadata); > > printf("%p: complete tx idx=%u addr=%llx\n", xsk, idx, addr); >- printf("%p: tx_timestamp: %llu (sec:%0.4f)\n", xsk, >- meta->completion.tx_timestamp, >+ >+ printf("tx_timestamp: %llu (sec:%0.4f)\n", >+meta->completion.tx_timestamp, > (double)meta->completion.tx_timestamp / NANOSEC_PER_SEC); >+ if (meta->completion.tx_timestamp) { >+ __u64 ref_tstamp = gettime(clock_id); >+ >+ print_tstamp_delta("HW TX-complete-time", "CLOCK_TAI", meta- >>completion.tx_timestamp, ref_tstamp); >+ print_tstamp_delta("SW RX-time", "CLOCK_TAI", >last_sw_rx_timestamp, ref_tstamp); >+ print_tstamp_delta("HW RX-time", "HW TX-complete-time", >last_hw_rx_timestamp, meta->completion.tx_timestamp); >+ } >+ > xsk_ring_cons__release(&xsk->comp, 1); > > return true; >@@ -276,7 +289,7 @@ static bool complete_tx(struct xsk *xsk) > } \ > } while (0) > >-static void ping_pong(struct xsk *xsk, void *rx_packet) >+static void ping_pong(struct xsk *xsk, void *rx_packet, clockid_t >+clock_id) > { > struct xsk_tx_metadata *meta; > struct ipv6hdr *ip6h = NULL; >@@ -418,14 +431,14 @@ static int verify_metadata(struct xsk *rx_xsk, int rxq, int >server_fd, clockid_t > > if (!skip_tx) { > /* mirror the packet back */ >- ping_pong(xsk, xsk_umem__get_data(xsk- >>umem_area, addr)); >+ ping_pong(xsk, xsk_umem__get_data(xsk- >>umem_area, addr), clock_id); > > ret = kick_tx(xsk); > if (ret) > printf("kick_tx ret=%d\n", ret); > > for (int j = 0; j < 500; j++) { >- if (complete_tx(xsk)) >+ if (complete_tx(xsk, clock_id)) > break; > usleep(10*1000); > } > > >> > > 0x1062cb8: complete rx idx=128 addr=80100 >> > > >> > > mvbz4:~# nc -Nu -q1 ${MVBZ3_LINK_LOCAL_IP}%eth3 9091 >> > > >> > > mvbz4:~# tcpdump -vvx -i eth3 udp >> > > tcpdump: listening on eth3, link-type EN10MB (Ethernet), snapshot >> > > length 262144 bytes >> > > 12:26:09.301074 IP6 (flowlabel 0x35fa5, hlim 127, next-header UDP (17) >payload length: 11) fe80::1270:fdff:fe48:1087.55807 > >fe80::1270:fdff:fe48:1077.9091: [bad udp cksum 0x3b8e -> 0xde7e!] UDP, length 3 >> > > 0x0000: 6003 5fa5 000b 117f fe80 0000 0000 0000 >> > > 0x0010: 1270 fdff fe48 1087 fe80 0000 0000 0000 >> > > 0x0020: 1270 fdff fe48 1077 d9ff 2383 000b 3b8e >> > > 0x0030: 7864 70 >> > > 12:26:09.301976 IP6 (flowlabel 0x35fa5, hlim 127, next-header UDP (17) >payload length: 11) fe80::1270:fdff:fe48:1077.9091 > >fe80::1270:fdff:fe48:1087.55807: [udp sum ok] UDP, length 3 >> > > 0x0000: 6003 5fa5 000b 117f fe80 0000 0000 0000 >> > > 0x0010: 1270 fdff fe48 1077 fe80 0000 0000 0000 >> > > 0x0020: 1270 fdff fe48 1087 2383 d9ff 000b de7e >> > > 0x0030: 7864 70 >> > > >> > > Signed-off-by: Stanislav Fomichev <sdf@...gle.com> >> > > --- >> > > tools/testing/selftests/bpf/xdp_hw_metadata.c | 202 >+++++++++++++++++- >> > > 1 file changed, 192 insertions(+), 10 deletions(-) >> > > >> > > diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c >> > > b/tools/testing/selftests/bpf/xdp_hw_metadata.c >> > > index 613321eb84c1..ab83d0ba6763 100644 >> > > --- a/tools/testing/selftests/bpf/xdp_hw_metadata.c >> > > +++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c >> > > @@ -10,7 +10,9 @@ >> > > * - rx_hash >> > > * >> > > * TX: >> > > - * - TBD >> > > + * - UDP 9091 packets trigger TX reply >> > > + * - TX HW timestamp is requested and reported back upon >> > > + completion >> > > + * - TX checksum is requested >> > > */ >> > > #include <test_progs.h> >> > > @@ -24,14 +26,17 @@ >> > [...] >> > > @@ -51,22 +56,24 @@ struct xsk *rx_xsk; >> > [...] >> > > @@ -129,12 +136,22 @@ static void refill_rx(struct xsk *xsk, __u64 >> > > addr) >> > [...] >> > > @@ -228,6 +245,117 @@ static void verify_skb_metadata(int fd) >> > > printf("skb hwtstamp is not found!\n"); >> > > } >> > > +static bool complete_tx(struct xsk *xsk) { >> > > + struct xsk_tx_metadata *meta; >> > > + __u64 addr; >> > > + void *data; >> > > + __u32 idx; >> > > + >> > > + if (!xsk_ring_cons__peek(&xsk->comp, 1, &idx)) >> > > + return false; >> > > + >> > > + addr = *xsk_ring_cons__comp_addr(&xsk->comp, idx); >> > > + data = xsk_umem__get_data(xsk->umem_area, addr); >> > > + meta = data - sizeof(struct xsk_tx_metadata); >> > > + >> > > + printf("%p: complete tx idx=%u addr=%llx\n", xsk, idx, addr); >> > > + printf("%p: tx_timestamp: %llu (sec:%0.4f)\n", xsk, >> > > + meta->completion.tx_timestamp, >> > > + (double)meta->completion.tx_timestamp / NANOSEC_PER_SEC); >> > > + xsk_ring_cons__release(&xsk->comp, 1); >> > > + >> > > + return true; >> > > +} >> > > + >> > > +#define swap(a, b, len) do { \ >> > > + for (int i = 0; i < len; i++) { \ >> > > + __u8 tmp = ((__u8 *)a)[i]; \ >> > > + ((__u8 *)a)[i] = ((__u8 *)b)[i]; \ >> > > + ((__u8 *)b)[i] = tmp; \ >> > > + } \ >> > > +} while (0) >> > > + >> > > +static void ping_pong(struct xsk *xsk, void *rx_packet) { >> > > + struct xsk_tx_metadata *meta; >> > > + struct ipv6hdr *ip6h = NULL; >> > > + struct iphdr *iph = NULL; >> > > + struct xdp_desc *tx_desc; >> > > + struct udphdr *udph; >> > > + struct ethhdr *eth; >> > > + __sum16 want_csum; >> > > + void *data; >> > > + __u32 idx; >> > > + int ret; >> > > + int len; >> > > + >> > > + ret = xsk_ring_prod__reserve(&xsk->tx, 1, &idx); >> > > + if (ret != 1) { >> > > + printf("%p: failed to reserve tx slot\n", xsk); >> > > + return; >> > > + } >> > > + >> > > + tx_desc = xsk_ring_prod__tx_desc(&xsk->tx, idx); >> > > + tx_desc->addr = idx % (UMEM_NUM / 2) * UMEM_FRAME_SIZE + >sizeof(struct xsk_tx_metadata); >> > > + data = xsk_umem__get_data(xsk->umem_area, tx_desc->addr); >> > > + >> > > + meta = data - sizeof(struct xsk_tx_metadata); >> > > + memset(meta, 0, sizeof(*meta)); >> > > + meta->flags = XDP_TX_METADATA_TIMESTAMP; >> > > + >> > > + eth = rx_packet; >> > > + >> > > + if (eth->h_proto == htons(ETH_P_IP)) { >> > > + iph = (void *)(eth + 1); >> > > + udph = (void *)(iph + 1); >> > > + } else if (eth->h_proto == htons(ETH_P_IPV6)) { >> > > + ip6h = (void *)(eth + 1); >> > > + udph = (void *)(ip6h + 1); >> > > + } else { >> > > + printf("%p: failed to detect IP version for ping pong %04x\n", xsk, >eth->h_proto); >> > > + xsk_ring_prod__cancel(&xsk->tx, 1); >> > > + return; >> > > + } >> > > + >> > > + len = ETH_HLEN; >> > > + if (ip6h) >> > > + len += sizeof(*ip6h) + ntohs(ip6h->payload_len); >> > > + if (iph) >> > > + len += ntohs(iph->tot_len); >> > > + >> > > + swap(eth->h_dest, eth->h_source, ETH_ALEN); >> > > + if (iph) >> > > + swap(&iph->saddr, &iph->daddr, 4); >> > > + else >> > > + swap(&ip6h->saddr, &ip6h->daddr, 16); >> > > + swap(&udph->source, &udph->dest, 2); >> > > + >> > > + want_csum = udph->check; >> > > + if (ip6h) >> > > + udph->check = ~csum_ipv6_magic(&ip6h->saddr, &ip6h->daddr, >> > > + ntohs(udph->len), IPPROTO_UDP, 0); >> > > + else >> > > + udph->check = ~csum_tcpudp_magic(iph->saddr, iph->daddr, >> > > + ntohs(udph->len), >IPPROTO_UDP, 0); >> > > + >> > > + meta->flags |= XDP_TX_METADATA_CHECKSUM; >> > > + if (iph) >> > > + meta->csum_start = sizeof(*eth) + sizeof(*iph); >> > > + else >> > > + meta->csum_start = sizeof(*eth) + sizeof(*ip6h); >> > > + meta->csum_offset = offsetof(struct udphdr, check); >> > > + >> > > + printf("%p: ping-pong with csum=%04x (want %04x) csum_start=%d >csum_offset=%d\n", >> > > + xsk, ntohs(udph->check), ntohs(want_csum), >> > > +meta->csum_start, meta->csum_offset); >> > > + >> > > + memcpy(data, rx_packet, len); /* don't share umem chunk for simplicity >*/ >> > > + tx_desc->options |= XDP_TX_METADATA; >> > > + tx_desc->len = len; >> > > + >> > > + xsk_ring_prod__submit(&xsk->tx, 1); } >> > > + >> > > static int verify_metadata(struct xsk *rx_xsk, int rxq, int server_fd, clockid_t >clock_id) >> > > { >> > > const struct xdp_desc *rx_desc; @@ -250,6 +378,13 @@ static int >> > > verify_metadata(struct xsk *rx_xsk, int rxq, int server_fd, clockid_t >> > > while (true) { >> > > errno = 0; >> > > + >> > > + for (i = 0; i < rxq; i++) { >> > > + ret = kick_rx(&rx_xsk[i]); >> > > + if (ret) >> > > + printf("kick_rx ret=%d\n", ret); >> > > + } >> > > + >> > > ret = poll(fds, rxq + 1, 1000); >> > > printf("poll: %d (%d) skip=%llu fail=%llu redir=%llu\n", >> > > ret, errno, bpf_obj->bss->pkts_skip, @@ -280,6 +415,22 >> > > @@ static int verify_metadata(struct xsk *rx_xsk, int rxq, int server_fd, >clockid_t >> > > xsk, idx, rx_desc->addr, addr, comp_addr); >> > > verify_xdp_metadata(xsk_umem__get_data(xsk- >>umem_area, addr), >> > > clock_id); >> > > + >> > > + if (!skip_tx) { >> > > + /* mirror the packet back */ >> > > + ping_pong(xsk, xsk_umem__get_data(xsk- >>umem_area, addr)); >> > > + >> > > + ret = kick_tx(xsk); >> > > + if (ret) >> > > + printf("kick_tx ret=%d\n", ret); >> > > + >> > > + for (int j = 0; j < 500; j++) { >> > > + if (complete_tx(xsk)) >> > > + break; >> > > + usleep(10*1000); >> > >> > I don't fully follow why we need this usleep here. >> >> To avoid the busypoll here (since we don't care too much about perf in >> the test). But I agree, should be ok to drop, will do. > >I take that back, I have to keep it. Otherwise I don't have a good bound on when to >stop/abort when waiting for completion. (and the number of loops needs to go >from 500 to unsure-how-many).
Powered by blists - more mailing lists