From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mails.dpdk.org (mails.dpdk.org [217.70.189.124]) by inbox.dpdk.org (Postfix) with ESMTP id E2DEB42602 for ; Thu, 21 Sep 2023 07:14:27 +0200 (CEST) Received: from mails.dpdk.org (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id A59894026D; Thu, 21 Sep 2023 07:14:27 +0200 (CEST) Received: from mail-lj1-f172.google.com (mail-lj1-f172.google.com [209.85.208.172]) by mails.dpdk.org (Postfix) with ESMTP id 04BD14014F for ; Thu, 21 Sep 2023 07:14:27 +0200 (CEST) Received: by mail-lj1-f172.google.com with SMTP id 38308e7fff4ca-2bb9a063f26so7938361fa.2 for ; Wed, 20 Sep 2023 22:14:26 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1695273266; x=1695878066; darn=dpdk.org; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:from:to:cc:subject:date :message-id:reply-to; bh=llZhmqYvbDKbtxrdMDH/7aMWdM2duGw7B/ShZMIY2dw=; b=QaVylh6Q8ahzhLticqg/aGx0ppt9Bd1ET4IjXyAT2GZzMW8N2DL2UxiXGQIex2eIp8 jeYiTN/93w2Qvd0CgF6p9G1d9ZLEOttq4YBwOC287EizAPnxM/gL3+uZsDnc/6C0Pfon PYLaSD4D9PVui+K/Sf0qMWBX+6+CXapk99+QsDI3KmKOAAuHrMr4nLAokPEo+k+kWttV 5apXCQYntaRNHhwykH7ScxsifaspZ+7ycWd4ce6ZmvyHc/wEvZ22FeqmNH1LwGGwbRtt jtOhqgdeWlX2Y7IAbb8lfaKa1BYAV1GPHjcE9ysDp/vdgsrI1LSaljmzqWUDwyUle6ue 8enA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1695273266; x=1695878066; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=llZhmqYvbDKbtxrdMDH/7aMWdM2duGw7B/ShZMIY2dw=; b=kTMsK17algzVK8YzLpy7semqiWsvrapLQSrK1PYwOWwn+UqZdsORMPkFvBt1RxScpt EbRg70uA1O1auMf9zVhf+TY9WS4FX/zDXJXNo+y1dyl0dwSzDglQkMOZoH6QYkHF1oQ0 mgNpwwufvpv2iSGDJDA3PgTSZJrDj357VCw6LpVUjx4CK8NwAHvPUjY2S5uyy8blQyin mPVfl8zstJ10wV2mHUBEG+EKoZl3p8IF827Zrp9m/cBEjqXbLKbf+RMCc9lH5jHLR6VC lKxnX1Ka4PNU9UKJPYDx0PMo+ZjyOgVbvXdxJbAqvbVzOz9q0c5EXr5Z+Bpbdr8BmMgs cVDw== X-Gm-Message-State: AOJu0YyN+RcOsbjlU5BgRr47SVQJVgVhP4RsgEnuc6oCyLr99oXsE38R znOgUxVudI6YOW/LC/ZzE89CFASvtNDk7oKZ7eq8pbWf X-Google-Smtp-Source: AGHT+IGDBmyB488XzXEuBonoKXmdATSRl3asjfpw8F0SaRsNmLMDNq9ziNv7fVevQy1KvUez6LCbijbRQ+AHZJ4QlWI= X-Received: by 2002:a2e:9dd4:0:b0:2c0:3284:64d5 with SMTP id x20-20020a2e9dd4000000b002c0328464d5mr3715398ljj.47.1695273266014; Wed, 20 Sep 2023 22:14:26 -0700 (PDT) MIME-Version: 1.0 References: <20230919110009.29e90615@hermes.local> <20230920190950.5acdae45@hermes.local> In-Reply-To: <20230920190950.5acdae45@hermes.local> From: Isaac Boukris Date: Thu, 21 Sep 2023 08:14:12 +0300 Message-ID: Subject: Re: dumpcap: timestamp is years ahead when in pcapng format To: Stephen Hemminger Cc: users@dpdk.org Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-BeenThere: users@dpdk.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: DPDK usage discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: users-bounces@dpdk.org On Thu, Sep 21, 2023 at 5:09=E2=80=AFAM Stephen Hemminger wrote: > > On Wed, 20 Sep 2023 22:55:21 +0300 > Isaac Boukris wrote: > > > I found a way to get a better resolution; at init we set > > 'pcapng_time.tsc_hz=3Drte_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=3D0? 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=E2=80=AFPM Isaac Boukris 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 ge= t > > > 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=E2=80=AFPM Isaac Boukris wrote: > > > > > > > > On Tue, Sep 19, 2023 at 9:00=E2=80=AFPM Stephen Hemminger > > > > wrote: > > > > > > > > > > On Tue, 19 Sep 2023 19:35:55 +0300 > > > > > Isaac Boukris 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: 3= 1975 > > > > > > NXDomain 0/0/0 (46) = 10 > > > > > > 2023-09-19 08:05:21.577497 ARP, Request who-has _gateway tell R= ocky8, > > > > > > length 46 > > > > > > 2023-09-19 08:05:21.577599 ARP, Reply _gateway is-at 00:50:56:f= 8: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 d= ropped > > > > > > all the parenthesis: > > > > > > return pcapng_time.ns + delta / pcapng_time.tsc_hz * NSEC_PER_S= EC; > > > > > > > > > > The issue is that timestamping is in the fast path and that 64 bi= t 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_S= EC > > > > 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 o= nly > > > > change to multiply after the division, then all packets are shown f= rom > > > > 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 =3D cycles - pcapng_time.cycles; > > > > - if (unlikely(delta >=3D pcapng_time.tsc_hz)) { > > > > + if (0 && unlikely(delta >=3D pcapng_time.tsc_hz)) { > > > > if (likely(delta < pcapng_time.tsc_hz * 2)) { > > > > delta -=3D pcapng_time.tsc_hz; > > > > pcapng_time.cycles +=3D 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 * N= SEC_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!