From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail.ozlabs.org (mail.ozlabs.org [IPv6:2404:9400:2221:ea00::3]) by passt.top (Postfix) with ESMTPS id 767745A004E for ; Fri, 26 Jul 2024 01:16:14 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202312; t=1721949364; bh=UsJ9QCDdnSxuPQos6Dh74Abvl4oKNO23w39kuZTp2zU=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=gYSY+1F61ARLffU3DN7pL0kB0hrlle/zhu8CT+n8z1hdob/PCbLzxx97G+cATerXR 8vkTASKYELA+AuLATQF316cFhApxMiCLrSfNArlrnOPioLJLBXF1uGIQslULo0newJ gtIYDlleUaKBI0JtAmIRKZGTOE5S/NgACak3HJyCAcl1/9D6pTVhs3o9iDdsp/0SVh DfaaaEmnKe9ga/xLc29PUvnn+hVnkY8+8KCO/b00Gd4gzA+QWGuBHtZvex4cvjGb9u u710/ST4++SuwVci4IZ75A5SKyuxOXVknfQd3tbJ8AKoWN2z5FsTK3lxzBGIjHdMes w+IAzz2//HyBQ== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4WVRZr70Bxz4x1V; Fri, 26 Jul 2024 09:16:04 +1000 (AEST) Date: Fri, 26 Jul 2024 09:11:32 +1000 From: David Gibson To: Stefano Brivio Subject: Re: [PATCH 1/3] log, util: Fix sub-second part in relative log time calculation Message-ID: References: <20240725162634.107697-1-sbrivio@redhat.com> <20240725162634.107697-2-sbrivio@redhat.com> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="nndftkHJMG6UcSeU" Content-Disposition: inline In-Reply-To: <20240725162634.107697-2-sbrivio@redhat.com> Message-ID-Hash: VNCIURO2CEOUBS35NILFBG4ROAO75ESV X-Message-ID-Hash: VNCIURO2CEOUBS35NILFBG4ROAO75ESV X-MailFrom: dgibson@gandalf.ozlabs.org X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: passt-dev@passt.top X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: --nndftkHJMG6UcSeU Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable On Thu, Jul 25, 2024 at 06:26:32PM +0200, Stefano Brivio wrote: > For some reason, in commit 01efc71ddd25 ("log, conf: Add support for > logging to file"), I added calculations for relative logging > timestamps using the difference for the seconds part only, not for > accounting for the fractional part. >=20 > Fix that by storing the initial timestamp, log_start, as a timespec > struct, and by calculating the difference from the starting time. Do > this in a macro as we need the same format in a few places. >=20 > To calculate the difference, turn the existing timespec_diff_ms() to > microseconds, timespec_diff_us(), and rewrite timespec_diff_ms() to > use that. >=20 > Signed-off-by: Stefano Brivio Reviewed-by: David Gibson > --- > log.c | 42 ++++++++++++++++++++++-------------------- > util.c | 25 ++++++++++++++++++------- > util.h | 1 + > 3 files changed, 41 insertions(+), 27 deletions(-) >=20 > diff --git a/log.c b/log.c > index 54483e7..32157a8 100644 > --- a/log.c > +++ b/log.c > @@ -40,12 +40,21 @@ static size_t log_written; /* Currently used bytes i= n log file */ > static size_t log_cut_size; /* Bytes to cut at start on rotation */ > static char log_header[BUFSIZ]; /* File header, written back on cuts */ > =20 > -static time_t log_start; /* Start timestamp */ > +static struct timespec log_start; /* Start timestamp */ > =20 > int log_trace; /* --trace mode enabled */ > bool log_conf_parsed; /* Logging options already parsed */ > bool log_runtime; /* Daemonised, or ready in foreground */ > =20 > +/** > + * logtime_fmt_and_arg() - Build format and arguments to print relative = log time > + * @x: Current timestamp > + */ > +#define logtime_fmt_and_arg(x) \ > + "%lli.%04lli", \ > + (timespec_diff_us((x), &log_start) / 1000000LL), \ > + (timespec_diff_us((x), &log_start) / 100LL) > + > /** > * vlogmsg() - Print or send messages to log or output files as configur= ed > * @newline: Append newline at the end of the message, if missing > @@ -60,9 +69,8 @@ void vlogmsg(bool newline, int pri, const char *format,= va_list ap) > =20 > if (debug_print) { > clock_gettime(CLOCK_REALTIME, &tp); > - fprintf(stderr, "%lli.%04lli: ", > - (long long int)tp.tv_sec - log_start, > - (long long int)tp.tv_nsec / (100L * 1000)); > + fprintf(stderr, logtime_fmt_and_arg(&tp)); > + fprintf(stderr, ": "); > } > =20 > if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { > @@ -144,12 +152,9 @@ void trace_init(int enable) > */ > void __openlog(const char *ident, int option, int facility) > { > - struct timespec tp; > - > (void)option; > =20 > - clock_gettime(CLOCK_REALTIME, &tp); > - log_start =3D tp.tv_sec; > + clock_gettime(CLOCK_REALTIME, &log_start); > =20 > if (log_sock < 0) { > struct sockaddr_un a =3D { .sun_family =3D AF_UNIX, }; > @@ -255,10 +260,8 @@ static void logfile_rotate_fallocate(int fd, const s= truct timespec *now) > if (read(fd, buf, BUFSIZ) =3D=3D -1) > return; > =20 > - n =3D snprintf(buf, BUFSIZ, > - "%s - log truncated at %lli.%04lli", log_header, > - (long long int)(now->tv_sec - log_start), > - (long long int)(now->tv_nsec / (100L * 1000))); > + n =3D snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header); > + n +=3D snprintf(buf + n, BUFSIZ - n, logtime_fmt_and_arg(now)); > =20 > /* Avoid partial lines by padding the header with spaces */ > nl =3D memchr(buf + n + 1, '\n', BUFSIZ - n - 1); > @@ -288,10 +291,11 @@ static void logfile_rotate_move(int fd, const struc= t timespec *now) > char buf[BUFSIZ]; > const char *nl; > =20 > - header_len =3D snprintf(buf, BUFSIZ, > - "%s - log truncated at %lli.%04lli\n", log_header, > - (long long int)(now->tv_sec - log_start), > - (long long int)(now->tv_nsec / (100L * 1000))); > + header_len =3D snprintf(buf, BUFSIZ, "%s - log truncated at ", > + log_header); > + header_len +=3D snprintf(buf + header_len, BUFSIZ - header_len, > + logtime_fmt_and_arg(now)); > + > if (lseek(fd, 0, SEEK_SET) =3D=3D -1) > return; > if (write(fd, buf, header_len) =3D=3D -1) > @@ -383,10 +387,8 @@ void logfile_write(bool newline, int pri, const char= *format, va_list ap) > if (clock_gettime(CLOCK_REALTIME, &now)) > return; > =20 > - n =3D snprintf(buf, BUFSIZ, "%lli.%04lli: %s", > - (long long int)(now.tv_sec - log_start), > - (long long int)(now.tv_nsec / (100L * 1000)), > - logfile_prefix[pri]); > + n =3D snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now)); > + n +=3D snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); > =20 > n +=3D vsnprintf(buf + n, BUFSIZ - n, format, ap); > =20 > diff --git a/util.c b/util.c > index c275b14..f2e26a7 100644 > --- a/util.c > +++ b/util.c > @@ -239,6 +239,23 @@ void sock_probe_mem(struct ctx *c) > close(s); > } > =20 > +/** > + * timespec_diff_us() - Report difference in microseconds between two ti= mestamps > + * @a: Minuend timestamp > + * @b: Subtrahend timestamp > + * > + * Return: difference in microseconds (wraps after 2^64 / 10^6s ~=3D 585= k years) > + */ > +long long timespec_diff_us(const struct timespec *a, const struct timesp= ec *b) > +{ > + if (a->tv_nsec < b->tv_nsec) { > + return (b->tv_nsec - a->tv_nsec) / 1000 + > + (a->tv_sec - b->tv_sec - 1) * 1000000; > + } > + > + return (a->tv_nsec - b->tv_nsec) / 1000 + > + (a->tv_sec - b->tv_sec) * 1000000; > +} > =20 > /** > * timespec_diff_ms() - Report difference in milliseconds between two ti= mestamps > @@ -249,13 +266,7 @@ void sock_probe_mem(struct ctx *c) > */ > long timespec_diff_ms(const struct timespec *a, const struct timespec *b) > { > - if (a->tv_nsec < b->tv_nsec) { > - return (b->tv_nsec - a->tv_nsec) / 1000000 + > - (a->tv_sec - b->tv_sec - 1) * 1000; > - } > - > - return (a->tv_nsec - b->tv_nsec) / 1000000 + > - (a->tv_sec - b->tv_sec) * 1000; > + return timespec_diff_us(a, b) / 1000; > } > =20 > /** > diff --git a/util.h b/util.h > index 826614c..6f44eab 100644 > --- a/util.h > +++ b/util.h > @@ -152,6 +152,7 @@ int sock_l4(const struct ctx *c, sa_family_t af, enum= epoll_type type, > uint32_t data); > void sock_probe_mem(struct ctx *c); > long timespec_diff_ms(const struct timespec *a, const struct timespec *b= ); > +long long timespec_diff_us(const struct timespec *a, const struct timesp= ec *b); > void bitmap_set(uint8_t *map, unsigned bit); > void bitmap_clear(uint8_t *map, unsigned bit); > bool bitmap_isset(const uint8_t *map, unsigned bit); --=20 David Gibson (he or they) | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you, not the other way | around. http://www.ozlabs.org/~dgibson --nndftkHJMG6UcSeU Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIzBAEBCAAdFiEEO+dNsU4E3yXUXRK2zQJF27ox2GcFAmai25MACgkQzQJF27ox 2GeOaQ//dj3kY/HDj49iHNQm5Nv5b8YhNuKH8dcpG+MfW3USg5474nYh4x81dpUZ I4snxGoKNSXWxVAnhNtRaZe74o2jPiDWdDgY1fDu6jtRF7E24G7gEgqrOX/bRQsk sx4Sl3u0i3LcET+VGPKaUhbDAckk8iXBMtYDNBT85dwjYAqjnr39M8ZYQqDmeUU6 bF/molIM83ayt7hhU9P4FbokhwnEqv3yot39Yy3S4xn7IYrr6ALfVcSnbxbW4rsc RRn6G9Zh6drjK6j9mr3hi+n0sI4rQXezKA8/ZoIxfE2Ps2OZglwSyUqUHGHza9Xs eojCRLIZoW00eILTNKvB78pkYzzxfMSTHzMxNVwoE+GYg5h4zBO8TuvSYVSNZXHb QpodNFCGvQcRZX84VuVLWdI+mc5wyYgDDO8Nlet8ZP6F2MoM99nnyBLunTZvwovZ StUFZtCtz7se5Z3+kKLUbGS9ZokQuZDvWgIx70EBEvVsHmgzLPh9ucPHZWLpo9es zAuXhHrKDI6DGeyoIRMF/C/RttBxPzwnlM9zRAP4Rj0/KUz2DwNhpBc7C+cvJyQ/ OQ7dxgBiCjY6m3EHZVBTMro5XtDwOnZLxTGIIR5CEaj34Y9UJNVhInf0jHwvQcq4 uaYnITht+rmVk10VScqJAPYgNTyCUsUmxENmWQFgmB3iDOWh8Jo= =7m2B -----END PGP SIGNATURE----- --nndftkHJMG6UcSeU--