* dumpcap: timestamp is years ahead when in pcapng format @ 2023-09-19 14:40 Isaac Boukris 2023-09-19 16:35 ` Isaac Boukris 0 siblings, 1 reply; 10+ messages in thread From: Isaac Boukris @ 2023-09-19 14:40 UTC (permalink / raw) To: users, Stephen Hemminger Hi Stephen, Machine: vm on a laptop with i7 core rte_get_timer_hz() = 2500000000 rte_get_tsc_hz() = 2500000000 This issue doesn't occur with pcap format, only with pcapng. When I capture on my system with dumpcap I get timestamp years ahead: [root@Rocky8 ~]# dpdk-dumpcap -i 0 -f 'not tcp port 22' -w - | tcpdump -ttttr - File: - reading from file -, link-type EN10MB (Ethernet) Packets captured: 0 dropped privs to tcpdump 2257-07-15 19:27:35.541912 IP _gateway.domain > Rocky8.36824: 42742 NXDomain 0/0/0 (44) 2257-07-15 19:27:35.541912 IP Rocky8.58223 > _gateway.domain: 22616+ PTR? 2.202.168.192.in-addr.arpa. (44) Looking at the code, I tried the below simplification in pcapng_tsc_to_ns() and it yielded good results, but I'm still not clear as the logic is quite intimidating. diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c index 80d08e1..96540b4 100644 --- a/lib/pcapng/rte_pcapng.c +++ b/lib/pcapng/rte_pcapng.c @@ -79,21 +79,8 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) * Currently all TSCs operate below 5GHz. */ delta = cycles - pcapng_time.cycles; - if (unlikely(delta >= pcapng_time.tsc_hz)) { - if (likely(delta < pcapng_time.tsc_hz * 2)) { - delta -= pcapng_time.tsc_hz; - pcapng_time.cycles += pcapng_time.tsc_hz; - pcapng_time.ns += NSEC_PER_SEC; - } else { - secs = rte_reciprocal_divide_u64(delta, &pcapng_time.tsc_hz_inverse); - delta -= secs * pcapng_time.tsc_hz; - pcapng_time.cycles += secs * pcapng_time.tsc_hz; - pcapng_time.ns += secs * NSEC_PER_SEC; - } - } - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, - &pcapng_time.tsc_hz_inverse); + return pcapng_time.ns + ((uint64_t)(delta / pcapng_time.tsc_hz) * NSEC_PER_SEC); Results: [root@Rocky8 ~]# dpdk-dumpcap -i 0 -f 'not tcp port 22' -w - | tcpdump -ttttr - File: - reading from file -, link-type EN10MB (Ethernet) Packets captured: 0 dropped privs to tcpdump 2023-09-19 05:33:18.191601 IP _gateway.domain > Rocky8.50821: 37740 NXDomain 0/0/0 (44) 2023-09-19 05:33:18.191601 IP Rocky8.57382 > _gateway.domain: 53422+ PTR? 2.202.168.192.in-addr.arpa. (44) Any thoughts on this? Thanks! ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-19 14:40 dumpcap: timestamp is years ahead when in pcapng format Isaac Boukris @ 2023-09-19 16:35 ` Isaac Boukris 2023-09-19 18:00 ` Stephen Hemminger 0 siblings, 1 reply; 10+ messages in thread From: Isaac Boukris @ 2023-09-19 16:35 UTC (permalink / raw) To: users, Stephen Hemminger Looking with git log, i found the original line was: return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); Testing that does show a wrapping issue, e.g. (it stays around 08:05). 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 NXDomain 0/0/0 (46) 10 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, length 46 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 (oui Unknown), length 46 13 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > 239.255.255.250.ssdp: UDP, length 174 However with my change it looks fine and always increments. I dropped all the parenthesis: return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; On Tue, Sep 19, 2023 at 5:40 PM Isaac Boukris <iboukris@gmail.com> wrote: > > Hi Stephen, > > Machine: vm on a laptop with i7 core > rte_get_timer_hz() = 2500000000 > rte_get_tsc_hz() = 2500000000 > > This issue doesn't occur with pcap format, only with pcapng. > When I capture on my system with dumpcap I get timestamp years ahead: > > [root@Rocky8 ~]# dpdk-dumpcap -i 0 -f 'not tcp port 22' -w - | tcpdump -ttttr - > File: - > reading from file -, link-type EN10MB (Ethernet) > Packets captured: 0 dropped privs to tcpdump > 2257-07-15 19:27:35.541912 IP _gateway.domain > Rocky8.36824: 42742 > NXDomain 0/0/0 (44) > 2257-07-15 19:27:35.541912 IP Rocky8.58223 > _gateway.domain: 22616+ > PTR? 2.202.168.192.in-addr.arpa. (44) > > Looking at the code, I tried the below simplification in > pcapng_tsc_to_ns() and it yielded good results, but I'm still not > clear as the logic is quite intimidating. > > diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c > index 80d08e1..96540b4 100644 > --- a/lib/pcapng/rte_pcapng.c > +++ b/lib/pcapng/rte_pcapng.c > @@ -79,21 +79,8 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > * Currently all TSCs operate below 5GHz. > */ > delta = cycles - pcapng_time.cycles; > - if (unlikely(delta >= pcapng_time.tsc_hz)) { > - if (likely(delta < pcapng_time.tsc_hz * 2)) { > - delta -= pcapng_time.tsc_hz; > - pcapng_time.cycles += pcapng_time.tsc_hz; > - pcapng_time.ns += NSEC_PER_SEC; > - } else { > - secs = rte_reciprocal_divide_u64(delta, > &pcapng_time.tsc_hz_inverse); > - delta -= secs * pcapng_time.tsc_hz; > - pcapng_time.cycles += secs * pcapng_time.tsc_hz; > - pcapng_time.ns += secs * NSEC_PER_SEC; > - } > - } > > - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, > - > &pcapng_time.tsc_hz_inverse); > + return pcapng_time.ns + ((uint64_t)(delta / > pcapng_time.tsc_hz) * NSEC_PER_SEC); > > Results: > > [root@Rocky8 ~]# dpdk-dumpcap -i 0 -f 'not tcp port 22' -w - | tcpdump -ttttr - > File: - > reading from file -, link-type EN10MB (Ethernet) > Packets captured: 0 dropped privs to tcpdump > 2023-09-19 05:33:18.191601 IP _gateway.domain > Rocky8.50821: 37740 > NXDomain 0/0/0 (44) > 2023-09-19 05:33:18.191601 IP Rocky8.57382 > _gateway.domain: 53422+ > PTR? 2.202.168.192.in-addr.arpa. (44) > > Any thoughts on this? > > Thanks! ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-19 16:35 ` Isaac Boukris @ 2023-09-19 18:00 ` Stephen Hemminger 2023-09-20 17:59 ` Isaac Boukris 0 siblings, 1 reply; 10+ messages in thread From: Stephen Hemminger @ 2023-09-19 18:00 UTC (permalink / raw) To: Isaac Boukris; +Cc: users On Tue, 19 Sep 2023 19:35:55 +0300 Isaac Boukris <iboukris@gmail.com> wrote: > Looking with git log, i found the original line was: > return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); > > Testing that does show a wrapping issue, e.g. (it stays around 08:05). > > 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 > NXDomain 0/0/0 (46) 10 > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, > length 46 > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 > (oui Unknown), length 46 13 > 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > > 239.255.255.250.ssdp: UDP, length 174 > > However with my change it looks fine and always increments. I dropped > all the parenthesis: > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; The issue is that timestamping is in the fast path and that 64 bit divide is slow. Looking at other alternatives. ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-19 18:00 ` Stephen Hemminger @ 2023-09-20 17:59 ` Isaac Boukris 2023-09-20 18:53 ` Isaac Boukris 0 siblings, 1 reply; 10+ messages in thread From: Isaac Boukris @ 2023-09-20 17:59 UTC (permalink / raw) To: Stephen Hemminger; +Cc: users On Tue, Sep 19, 2023 at 9:00 PM Stephen Hemminger <stephen@networkplumber.org> wrote: > > On Tue, 19 Sep 2023 19:35:55 +0300 > Isaac Boukris <iboukris@gmail.com> wrote: > > > Looking with git log, i found the original line was: > > return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); > > > > Testing that does show a wrapping issue, e.g. (it stays around 08:05). > > > > 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 > > NXDomain 0/0/0 (46) 10 > > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, > > length 46 > > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 > > (oui Unknown), length 46 13 > > 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > > > 239.255.255.250.ssdp: UDP, length 174 > > > > However with my change it looks fine and always increments. I dropped > > all the parenthesis: > > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; > > The issue is that timestamping is in the fast path and that 64 bit divide is slow. > Looking at other alternatives. Then perhaps we can keep the division optimization and just get rid of the overflow check, relying on the change to multiply by NSEC_PER_SEC after the division. With the below change only the first packet is from 2257 while all subsequent packets are fine. But if I keep the overflow check and only change to multiply after the division, then all packets are shown from 2257. [admin@Rocky8 dpdk]$ git diff lib/pcapng/rte_pcapng.c diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c index 80d08e1..fa545cd 100644 --- a/lib/pcapng/rte_pcapng.c +++ b/lib/pcapng/rte_pcapng.c @@ -79,7 +79,7 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) * Currently all TSCs operate below 5GHz. */ delta = cycles - pcapng_time.cycles; - if (unlikely(delta >= pcapng_time.tsc_hz)) { + if (0 && unlikely(delta >= pcapng_time.tsc_hz)) { if (likely(delta < pcapng_time.tsc_hz * 2)) { delta -= pcapng_time.tsc_hz; pcapng_time.cycles += pcapng_time.tsc_hz; @@ -92,8 +92,9 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) } } - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, - &pcapng_time.tsc_hz_inverse); + return pcapng_time.ns + rte_reciprocal_divide_u64(delta, + &pcapng_time.tsc_hz_inverse) * NSEC_PER_SEC; } ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-20 17:59 ` Isaac Boukris @ 2023-09-20 18:53 ` Isaac Boukris 2023-09-20 19:55 ` Isaac Boukris 0 siblings, 1 reply; 10+ messages in thread From: Isaac Boukris @ 2023-09-20 18:53 UTC (permalink / raw) To: Stephen Hemminger; +Cc: users I figured the first packet bug, fixed with: - if (!pcapng_time.tsc_hz) + if (!pcapng_time.tsc_hz) { pcapng_init(); + return pcapng_time.ns; + } However I noticed a caveat with my proposed fix as it seem we only get a time resolution of one sec: 2023-09-20 09:40:20.727638 IP Rocky8 > A: ICMP echo request, id 11, seq 81, length 64 2023-09-20 09:40:20.727638 IP A > Rocky8: ICMP echo reply, id 11, seq 81, length 64 2023-09-20 09:40:21.727638 IP ... On Wed, Sep 20, 2023 at 8:59 PM Isaac Boukris <iboukris@gmail.com> wrote: > > On Tue, Sep 19, 2023 at 9:00 PM Stephen Hemminger > <stephen@networkplumber.org> wrote: > > > > On Tue, 19 Sep 2023 19:35:55 +0300 > > Isaac Boukris <iboukris@gmail.com> wrote: > > > > > Looking with git log, i found the original line was: > > > return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); > > > > > > Testing that does show a wrapping issue, e.g. (it stays around 08:05). > > > > > > 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 > > > NXDomain 0/0/0 (46) 10 > > > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, > > > length 46 > > > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 > > > (oui Unknown), length 46 13 > > > 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > > > > 239.255.255.250.ssdp: UDP, length 174 > > > > > > However with my change it looks fine and always increments. I dropped > > > all the parenthesis: > > > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; > > > > The issue is that timestamping is in the fast path and that 64 bit divide is slow. > > Looking at other alternatives. > > Then perhaps we can keep the division optimization and just get rid of > the overflow check, relying on the change to multiply by NSEC_PER_SEC > after the division. > > With the below change only the first packet is from 2257 while all > subsequent packets are fine. But if I keep the overflow check and only > change to multiply after the division, then all packets are shown from > 2257. > > [admin@Rocky8 dpdk]$ git diff lib/pcapng/rte_pcapng.c > diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c > index 80d08e1..fa545cd 100644 > --- a/lib/pcapng/rte_pcapng.c > +++ b/lib/pcapng/rte_pcapng.c > @@ -79,7 +79,7 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > * Currently all TSCs operate below 5GHz. > */ > delta = cycles - pcapng_time.cycles; > - if (unlikely(delta >= pcapng_time.tsc_hz)) { > + if (0 && unlikely(delta >= pcapng_time.tsc_hz)) { > if (likely(delta < pcapng_time.tsc_hz * 2)) { > delta -= pcapng_time.tsc_hz; > pcapng_time.cycles += pcapng_time.tsc_hz; > @@ -92,8 +92,9 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > } > } > > - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, > - > &pcapng_time.tsc_hz_inverse); > + return pcapng_time.ns + rte_reciprocal_divide_u64(delta, > + > &pcapng_time.tsc_hz_inverse) * NSEC_PER_SEC; > } ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-20 18:53 ` Isaac Boukris @ 2023-09-20 19:55 ` Isaac Boukris 2023-09-21 2:09 ` Stephen Hemminger 0 siblings, 1 reply; 10+ messages in thread From: Isaac Boukris @ 2023-09-20 19:55 UTC (permalink / raw) To: Stephen Hemminger; +Cc: users [-- Attachment #1: Type: text/plain, Size: 4323 bytes --] I found a way to get a better resolution; at init we set 'pcapng_time.tsc_hz=rte_get_tsc_hz()/NSEC_PER_SEC' this way we keep the number of cycles in a nano-second, then at run time we just need to divide delta by this number (with no need to multiply by NSEC_PER_SEC). The problem is I guess, that on slow systems we'll end up with tsc_hz=0? Perhaps we'd need to drop to ms resolution in such a case. With the attach patch I get: 2023-09-20 10:22:13.579219 IP Rocky8 > A: ICMP echo request, id 13, seq 63, length 64 2023-09-20 10:22:13.580582 IP A > Rocky8: ICMP echo reply, id 13, seq 63, length 64 3 2023-09-20 10:22:14.745176 IP Rocky8 > A: ICMP echo request, id 13, seq 64, length 64 2023-09-20 10:22:14.746206 IP ... On Wed, Sep 20, 2023 at 9:53 PM Isaac Boukris <iboukris@gmail.com> wrote: > > I figured the first packet bug, fixed with: > - if (!pcapng_time.tsc_hz) > + if (!pcapng_time.tsc_hz) { > pcapng_init(); > + return pcapng_time.ns; > + } > > However I noticed a caveat with my proposed fix as it seem we only get > a time resolution of one sec: > > 2023-09-20 09:40:20.727638 IP Rocky8 > A: ICMP echo request, id 11, > seq 81, length 64 > 2023-09-20 09:40:20.727638 IP A > Rocky8: ICMP echo reply, id 11, seq > 81, length 64 > 2023-09-20 09:40:21.727638 IP ... > > On Wed, Sep 20, 2023 at 8:59 PM Isaac Boukris <iboukris@gmail.com> wrote: > > > > On Tue, Sep 19, 2023 at 9:00 PM Stephen Hemminger > > <stephen@networkplumber.org> wrote: > > > > > > On Tue, 19 Sep 2023 19:35:55 +0300 > > > Isaac Boukris <iboukris@gmail.com> wrote: > > > > > > > Looking with git log, i found the original line was: > > > > return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); > > > > > > > > Testing that does show a wrapping issue, e.g. (it stays around 08:05). > > > > > > > > 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 > > > > NXDomain 0/0/0 (46) 10 > > > > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, > > > > length 46 > > > > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 > > > > (oui Unknown), length 46 13 > > > > 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > > > > > 239.255.255.250.ssdp: UDP, length 174 > > > > > > > > However with my change it looks fine and always increments. I dropped > > > > all the parenthesis: > > > > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; > > > > > > The issue is that timestamping is in the fast path and that 64 bit divide is slow. > > > Looking at other alternatives. > > > > Then perhaps we can keep the division optimization and just get rid of > > the overflow check, relying on the change to multiply by NSEC_PER_SEC > > after the division. > > > > With the below change only the first packet is from 2257 while all > > subsequent packets are fine. But if I keep the overflow check and only > > change to multiply after the division, then all packets are shown from > > 2257. > > > > [admin@Rocky8 dpdk]$ git diff lib/pcapng/rte_pcapng.c > > diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c > > index 80d08e1..fa545cd 100644 > > --- a/lib/pcapng/rte_pcapng.c > > +++ b/lib/pcapng/rte_pcapng.c > > @@ -79,7 +79,7 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > > * Currently all TSCs operate below 5GHz. > > */ > > delta = cycles - pcapng_time.cycles; > > - if (unlikely(delta >= pcapng_time.tsc_hz)) { > > + if (0 && unlikely(delta >= pcapng_time.tsc_hz)) { > > if (likely(delta < pcapng_time.tsc_hz * 2)) { > > delta -= pcapng_time.tsc_hz; > > pcapng_time.cycles += pcapng_time.tsc_hz; > > @@ -92,8 +92,9 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > > } > > } > > > > - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, > > - > > &pcapng_time.tsc_hz_inverse); > > + return pcapng_time.ns + rte_reciprocal_divide_u64(delta, > > + > > &pcapng_time.tsc_hz_inverse) * NSEC_PER_SEC; > > } [-- Attachment #2: rework_tsc_to_ns.patch --] [-- Type: application/octet-stream, Size: 2869 bytes --] From 5e7b5aab292db7220d6774f51c7937e0c3d5b329 Mon Sep 17 00:00:00 2001 From: Isaac Boukris <iboukris@gmail.com> Date: Wed, 20 Sep 2023 10:32:01 +0300 Subject: [PATCH] WIP: rework pcapng_tsc_to_ns() --- lib/pcapng/rte_pcapng.c | 35 +++++++---------------------------- 1 file changed, 7 insertions(+), 28 deletions(-) diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c index 3c91fc7764..4a32d2a40a 100644 --- a/lib/pcapng/rte_pcapng.c +++ b/lib/pcapng/rte_pcapng.c @@ -112,45 +112,24 @@ pcapng_init(void) pcapng_time.cycles = (pcapng_time.cycles + rte_get_tsc_cycles()) / 2; pcapng_time.ns = rte_timespec_to_ns(&ts); - pcapng_time.tsc_hz = rte_get_tsc_hz(); + pcapng_time.tsc_hz = rte_get_tsc_hz() / NSEC_PER_SEC; + if (pcapng_time.tsc_hz == 0) { /* ? */ } pcapng_time.tsc_hz_inverse = rte_reciprocal_value_u64(pcapng_time.tsc_hz); } /* PCAPNG timestamps are in nanoseconds */ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) { - uint64_t delta, secs; + uint64_t delta; - if (!pcapng_time.tsc_hz) + if (!pcapng_time.tsc_hz) { pcapng_init(); + return pcapng_time.ns; + } - /* In essence the calculation is: - * delta = (cycles - pcapng_time.cycles) * NSEC_PRE_SEC / rte_get_tsc_hz() - * but this overflows within 4 to 8 seconds depending on TSC frequency. - * Instead, if delta >= pcapng_time.tsc_hz: - * Increase pcapng_time.ns and pcapng_time.cycles by the number of - * whole seconds in delta and reduce delta accordingly. - * delta will therefore always lie in the interval [0, pcapng_time.tsc_hz), - * which will not overflow when multiplied by NSEC_PER_SEC provided the - * TSC frequency < approx 18.4GHz. - * - * Currently all TSCs operate below 5GHz. - */ delta = cycles - pcapng_time.cycles; - if (unlikely(delta >= pcapng_time.tsc_hz)) { - if (likely(delta < pcapng_time.tsc_hz * 2)) { - delta -= pcapng_time.tsc_hz; - pcapng_time.cycles += pcapng_time.tsc_hz; - pcapng_time.ns += NSEC_PER_SEC; - } else { - secs = rte_reciprocal_divide_u64(delta, &pcapng_time.tsc_hz_inverse); - delta -= secs * pcapng_time.tsc_hz; - pcapng_time.cycles += secs * pcapng_time.tsc_hz; - pcapng_time.ns += secs * NSEC_PER_SEC; - } - } - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, + return pcapng_time.ns + rte_reciprocal_divide_u64(delta, &pcapng_time.tsc_hz_inverse); } -- 2.39.3 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-20 19:55 ` Isaac Boukris @ 2023-09-21 2:09 ` Stephen Hemminger 2023-09-21 5:14 ` Isaac Boukris 0 siblings, 1 reply; 10+ messages in thread From: Stephen Hemminger @ 2023-09-21 2:09 UTC (permalink / raw) To: Isaac Boukris; +Cc: users On Wed, 20 Sep 2023 22:55:21 +0300 Isaac Boukris <iboukris@gmail.com> wrote: > I found a way to get a better resolution; at init we set > 'pcapng_time.tsc_hz=rte_get_tsc_hz()/NSEC_PER_SEC' this way we keep > the number of cycles in a nano-second, then at run time we just need > to divide delta by this number (with no need to multiply by > NSEC_PER_SEC). > > The problem is I guess, that on slow systems we'll end up with > tsc_hz=0? Perhaps we'd need to drop to ms resolution in such a case. > > With the attach patch I get: > > 2023-09-20 10:22:13.579219 IP Rocky8 > A: ICMP echo request, id 13, > seq 63, length 64 > 2023-09-20 10:22:13.580582 IP A > Rocky8: ICMP echo reply, id 13, seq > 63, length 64 3 > 2023-09-20 10:22:14.745176 IP Rocky8 > A: ICMP echo request, id 13, > seq 64, length 64 > 2023-09-20 10:22:14.746206 IP ... > > On Wed, Sep 20, 2023 at 9:53 PM Isaac Boukris <iboukris@gmail.com> wrote: > > > > I figured the first packet bug, fixed with: > > - if (!pcapng_time.tsc_hz) > > + if (!pcapng_time.tsc_hz) { > > pcapng_init(); > > + return pcapng_time.ns; > > + } > > > > However I noticed a caveat with my proposed fix as it seem we only get > > a time resolution of one sec: > > > > 2023-09-20 09:40:20.727638 IP Rocky8 > A: ICMP echo request, id 11, > > seq 81, length 64 > > 2023-09-20 09:40:20.727638 IP A > Rocky8: ICMP echo reply, id 11, seq > > 81, length 64 > > 2023-09-20 09:40:21.727638 IP ... > > > > On Wed, Sep 20, 2023 at 8:59 PM Isaac Boukris <iboukris@gmail.com> wrote: > > > > > > On Tue, Sep 19, 2023 at 9:00 PM Stephen Hemminger > > > <stephen@networkplumber.org> wrote: > > > > > > > > On Tue, 19 Sep 2023 19:35:55 +0300 > > > > Isaac Boukris <iboukris@gmail.com> wrote: > > > > > > > > > Looking with git log, i found the original line was: > > > > > return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); > > > > > > > > > > Testing that does show a wrapping issue, e.g. (it stays around 08:05). > > > > > > > > > > 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 > > > > > NXDomain 0/0/0 (46) 10 > > > > > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, > > > > > length 46 > > > > > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 > > > > > (oui Unknown), length 46 13 > > > > > 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > > > > > > 239.255.255.250.ssdp: UDP, length 174 > > > > > > > > > > However with my change it looks fine and always increments. I dropped > > > > > all the parenthesis: > > > > > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; > > > > > > > > The issue is that timestamping is in the fast path and that 64 bit divide is slow. > > > > Looking at other alternatives. > > > > > > Then perhaps we can keep the division optimization and just get rid of > > > the overflow check, relying on the change to multiply by NSEC_PER_SEC > > > after the division. > > > > > > With the below change only the first packet is from 2257 while all > > > subsequent packets are fine. But if I keep the overflow check and only > > > change to multiply after the division, then all packets are shown from > > > 2257. > > > > > > [admin@Rocky8 dpdk]$ git diff lib/pcapng/rte_pcapng.c > > > diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c > > > index 80d08e1..fa545cd 100644 > > > --- a/lib/pcapng/rte_pcapng.c > > > +++ b/lib/pcapng/rte_pcapng.c > > > @@ -79,7 +79,7 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > > > * Currently all TSCs operate below 5GHz. > > > */ > > > delta = cycles - pcapng_time.cycles; > > > - if (unlikely(delta >= pcapng_time.tsc_hz)) { > > > + if (0 && unlikely(delta >= pcapng_time.tsc_hz)) { > > > if (likely(delta < pcapng_time.tsc_hz * 2)) { > > > delta -= pcapng_time.tsc_hz; > > > pcapng_time.cycles += pcapng_time.tsc_hz; > > > @@ -92,8 +92,9 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > > > } > > > } > > > > > > - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, > > > - > > > &pcapng_time.tsc_hz_inverse); > > > + return pcapng_time.ns + rte_reciprocal_divide_u64(delta, > > > + > > > &pcapng_time.tsc_hz_inverse) * NSEC_PER_SEC; > > > } This is less accurate. The TSC (CPU clock frequency) is not necessarily an even multiple of nanoseconds. If you want to send patches please follow the contributing guidelines and run checkpatch on them. ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-21 2:09 ` Stephen Hemminger @ 2023-09-21 5:14 ` Isaac Boukris 2023-09-21 15:31 ` Stephen Hemminger 0 siblings, 1 reply; 10+ messages in thread From: Isaac Boukris @ 2023-09-21 5:14 UTC (permalink / raw) To: Stephen Hemminger; +Cc: users On Thu, Sep 21, 2023 at 5:09 AM Stephen Hemminger <stephen@networkplumber.org> wrote: > > On Wed, 20 Sep 2023 22:55:21 +0300 > Isaac Boukris <iboukris@gmail.com> wrote: > > > I found a way to get a better resolution; at init we set > > 'pcapng_time.tsc_hz=rte_get_tsc_hz()/NSEC_PER_SEC' this way we keep > > the number of cycles in a nano-second, then at run time we just need > > to divide delta by this number (with no need to multiply by > > NSEC_PER_SEC). > > > > The problem is I guess, that on slow systems we'll end up with > > tsc_hz=0? Perhaps we'd need to drop to ms resolution in such a case. > > > > With the attach patch I get: > > > > 2023-09-20 10:22:13.579219 IP Rocky8 > A: ICMP echo request, id 13, > > seq 63, length 64 > > 2023-09-20 10:22:13.580582 IP A > Rocky8: ICMP echo reply, id 13, seq > > 63, length 64 3 > > 2023-09-20 10:22:14.745176 IP Rocky8 > A: ICMP echo request, id 13, > > seq 64, length 64 > > 2023-09-20 10:22:14.746206 IP ... > > > > On Wed, Sep 20, 2023 at 9:53 PM Isaac Boukris <iboukris@gmail.com> wrote: > > > > > > I figured the first packet bug, fixed with: > > > - if (!pcapng_time.tsc_hz) > > > + if (!pcapng_time.tsc_hz) { > > > pcapng_init(); > > > + return pcapng_time.ns; > > > + } > > > > > > However I noticed a caveat with my proposed fix as it seem we only get > > > a time resolution of one sec: > > > > > > 2023-09-20 09:40:20.727638 IP Rocky8 > A: ICMP echo request, id 11, > > > seq 81, length 64 > > > 2023-09-20 09:40:20.727638 IP A > Rocky8: ICMP echo reply, id 11, seq > > > 81, length 64 > > > 2023-09-20 09:40:21.727638 IP ... > > > > > > On Wed, Sep 20, 2023 at 8:59 PM Isaac Boukris <iboukris@gmail.com> wrote: > > > > > > > > On Tue, Sep 19, 2023 at 9:00 PM Stephen Hemminger > > > > <stephen@networkplumber.org> wrote: > > > > > > > > > > On Tue, 19 Sep 2023 19:35:55 +0300 > > > > > Isaac Boukris <iboukris@gmail.com> wrote: > > > > > > > > > > > Looking with git log, i found the original line was: > > > > > > return pcapng_time.ns + (delta * NSEC_PER_SEC) / rte_get_tsc_hz(); > > > > > > > > > > > > Testing that does show a wrapping issue, e.g. (it stays around 08:05). > > > > > > > > > > > > 2023-09-19 08:05:24.372037 IP _gateway.domain > Rocky8.38358: 31975 > > > > > > NXDomain 0/0/0 (46) 10 > > > > > > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell Rocky8, > > > > > > length 46 > > > > > > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f8:92:76 > > > > > > (oui Unknown), length 46 13 > > > > > > 2023-09-19 08:05:22.833897 IP 192.168.202.1.50886 > > > > > > > 239.255.255.250.ssdp: UDP, length 174 > > > > > > > > > > > > However with my change it looks fine and always increments. I dropped > > > > > > all the parenthesis: > > > > > > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_SEC; > > > > > > > > > > The issue is that timestamping is in the fast path and that 64 bit divide is slow. > > > > > Looking at other alternatives. > > > > > > > > Then perhaps we can keep the division optimization and just get rid of > > > > the overflow check, relying on the change to multiply by NSEC_PER_SEC > > > > after the division. > > > > > > > > With the below change only the first packet is from 2257 while all > > > > subsequent packets are fine. But if I keep the overflow check and only > > > > change to multiply after the division, then all packets are shown from > > > > 2257. > > > > > > > > [admin@Rocky8 dpdk]$ git diff lib/pcapng/rte_pcapng.c > > > > diff --git a/lib/pcapng/rte_pcapng.c b/lib/pcapng/rte_pcapng.c > > > > index 80d08e1..fa545cd 100644 > > > > --- a/lib/pcapng/rte_pcapng.c > > > > +++ b/lib/pcapng/rte_pcapng.c > > > > @@ -79,7 +79,7 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > > > > * Currently all TSCs operate below 5GHz. > > > > */ > > > > delta = cycles - pcapng_time.cycles; > > > > - if (unlikely(delta >= pcapng_time.tsc_hz)) { > > > > + if (0 && unlikely(delta >= pcapng_time.tsc_hz)) { > > > > if (likely(delta < pcapng_time.tsc_hz * 2)) { > > > > delta -= pcapng_time.tsc_hz; > > > > pcapng_time.cycles += pcapng_time.tsc_hz; > > > > @@ -92,8 +92,9 @@ static uint64_t pcapng_tsc_to_ns(uint64_t cycles) > > > > } > > > > } > > > > > > > > - return pcapng_time.ns + rte_reciprocal_divide_u64(delta * NSEC_PER_SEC, > > > > - > > > > &pcapng_time.tsc_hz_inverse); > > > > + return pcapng_time.ns + rte_reciprocal_divide_u64(delta, > > > > + > > > > &pcapng_time.tsc_hz_inverse) * NSEC_PER_SEC; > > > > } > > This is less accurate. The TSC (CPU clock frequency) is not necessarily > an even multiple of nanoseconds. > > If you want to send patches please follow the contributing guidelines > and run checkpatch on them. Yeah, I realized that and tried to improve on it by dividing by less at init and multiplying by less at run time. However I noticed another problem with my patches, that there is a time gap that keeps growing for some reason, and I can't figure out what's wrong. I'll try some more and will gladly test anything proposed. Thanks! ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-21 5:14 ` Isaac Boukris @ 2023-09-21 15:31 ` Stephen Hemminger 2023-09-21 19:00 ` Isaac Boukris 0 siblings, 1 reply; 10+ messages in thread From: Stephen Hemminger @ 2023-09-21 15:31 UTC (permalink / raw) To: Isaac Boukris; +Cc: users On Thu, 21 Sep 2023 08:14:12 +0300 Isaac Boukris <iboukris@gmail.com> wrote: > > This is less accurate. The TSC (CPU clock frequency) is not necessarily > > an even multiple of nanoseconds. > > > > If you want to send patches please follow the contributing guidelines > > and run checkpatch on them. > > Yeah, I realized that and tried to improve on it by dividing by less > at init and multiplying by less at run time. However I noticed another > problem with my patches, that there is a time gap that keeps growing > for some reason, and I can't figure out what's wrong. I'll try some > more and will gladly test anything proposed. All this should be fixed in this patch series. https://patchwork.dpdk.org/project/dpdk/list/?series=29581 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: dumpcap: timestamp is years ahead when in pcapng format 2023-09-21 15:31 ` Stephen Hemminger @ 2023-09-21 19:00 ` Isaac Boukris 0 siblings, 0 replies; 10+ messages in thread From: Isaac Boukris @ 2023-09-21 19:00 UTC (permalink / raw) To: Stephen Hemminger; +Cc: users On Thu, Sep 21, 2023 at 6:32 PM Stephen Hemminger <stephen@networkplumber.org> wrote: > > On Thu, 21 Sep 2023 08:14:12 +0300 > Isaac Boukris <iboukris@gmail.com> wrote: > > > > This is less accurate. The TSC (CPU clock frequency) is not necessarily > > > an even multiple of nanoseconds. > > > > > > If you want to send patches please follow the contributing guidelines > > > and run checkpatch on them. > > > > Yeah, I realized that and tried to improve on it by dividing by less > > at init and multiplying by less at run time. However I noticed another > > problem with my patches, that there is a time gap that keeps growing > > for some reason, and I can't figure out what's wrong. I'll try some > > more and will gladly test anything proposed. > > All this should be fixed in this patch series. > https://patchwork.dpdk.org/project/dpdk/list/?series=29581 I tested it and indeed all is fixed now, wonderful :) Thanks a lot! ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2023-09-21 19:01 UTC | newest] Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2023-09-19 14:40 dumpcap: timestamp is years ahead when in pcapng format Isaac Boukris 2023-09-19 16:35 ` Isaac Boukris 2023-09-19 18:00 ` Stephen Hemminger 2023-09-20 17:59 ` Isaac Boukris 2023-09-20 18:53 ` Isaac Boukris 2023-09-20 19:55 ` Isaac Boukris 2023-09-21 2:09 ` Stephen Hemminger 2023-09-21 5:14 ` Isaac Boukris 2023-09-21 15:31 ` Stephen Hemminger 2023-09-21 19:00 ` Isaac Boukris
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).