Re: dumpcap: timestamp is years ahead when in pcapng format

[Stephen Hemminger <stephen@networkplumber.org>]

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.