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 282AE5A004F for ; Sat, 03 Aug 2024 11:33:32 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202312; t=1722677595; bh=c/o6dj2/YLAjrPJJt8SgcswBuWhxSIjVFU9mEsB0ABk=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=A4DutlWItGU45iwCI12ifLZXsQcVLS9EukFw34eMEQZ9kWS0fmyaEiiIFbreDkl/2 FLKfsI5luYMvcjzFWIBNAFJY8NQJN+TIBzcfZTObiiBvhBjnza8sAgIx8lCjetBz3I TB/d0QlseWHyXJQWHjw7kG3QGxC7xNRVgQILYoh4xG6ZxuwX7/bRPJBoumUW3QueuN Z+i6CY8iB3WSFmZh70Te2mKDFHuUGdf+0LRps2tTnwQUX0l30gNJ726DWi7VND/vVE accpyAluDzIuRGVPDxcVP3jf8efIuoBJFo70ACwkpoKYC12Choj/UkNeLlH7bIMxwD OX3AT+sco9hGw== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4WbcvH2tLgz4wd0; Sat, 3 Aug 2024 19:33:15 +1000 (AEST) Date: Sat, 3 Aug 2024 17:53:40 +1000 From: David Gibson To: Stefano Brivio Subject: Re: [PATCH 2/2] log: Avoid duplicate calls to clock_gettime() Message-ID: References: <20240729042300.280684-1-david@gibson.dropbear.id.au> <20240729042300.280684-3-david@gibson.dropbear.id.au> <20240729195502.01467e7c@elisabeth> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="ekinU7TsSCkK8uMX" Content-Disposition: inline In-Reply-To: <20240729195502.01467e7c@elisabeth> Message-ID-Hash: XNO4ZVHLGR4H6C66IT4TK6SUJSQP3Z4T X-Message-ID-Hash: XNO4ZVHLGR4H6C66IT4TK6SUJSQP3Z4T 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: --ekinU7TsSCkK8uMX Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable On Mon, Jul 29, 2024 at 07:55:02PM +0200, Stefano Brivio wrote: > On Mon, 29 Jul 2024 14:23:00 +1000 > David Gibson wrote: >=20 > > We use clock_gettime() to get a timestamp for the log in two places: > > - in vlogmsg(), which is used only for debug_print messages > > - in logfile_write() which is only used messages to the log file > >=20 > > These cases are mutually exclusive, so we don't ever print the same mes= sage > > with different timestamps, but that's not particularly obvious to see. > >=20 > > Refactor to have a single clock_gettime() call in vlogmsg() and use it = for > > all the places we need it. > >=20 > > Signed-off-by: David Gibson > > --- > > log.c | 17 ++++++++--------- > > 1 file changed, 8 insertions(+), 9 deletions(-) > >=20 > > diff --git a/log.c b/log.c > > index eb3a780a..418bdefd 100644 > > --- a/log.c > > +++ b/log.c > > @@ -199,19 +199,17 @@ static int logfile_rotate(int fd, const struct ti= mespec *now) > > * logfile_write() - Write entry to log file, trigger rotation if full > > * @newline: Append newline at the end of the message, if missing > > * @pri: Facility and level map, same as priority for vsyslog() > > + * @tp: Timestamp > > * @format: Same as vsyslog() format > > * @ap: Same as vsyslog() ap > > */ > > -static void logfile_write(bool newline, int pri, const char *format, v= a_list ap) > > +static void logfile_write(bool newline, int pri, const struct timespec= *tp, > > + const char *format, va_list ap) > > { > > - struct timespec now; > > char buf[BUFSIZ]; > > int n; > > =20 > > - if (clock_gettime(CLOCK_MONOTONIC, &now)) > > - return; > > - > > - n =3D snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now)); > > + n =3D snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp)); > > n +=3D snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); > > =20 > > n +=3D vsnprintf(buf + n, BUFSIZ - n, format, ap); > > @@ -219,7 +217,7 @@ static void logfile_write(bool newline, int pri, co= nst char *format, va_list ap) > > if (newline && format[strlen(format)] !=3D '\n') > > n +=3D snprintf(buf + n, BUFSIZ - n, "\n"); > > =20 > > - if ((log_written + n >=3D log_size) && logfile_rotate(log_file, &now)) > > + if ((log_written + n >=3D log_size) && logfile_rotate(log_file, tp)) > > return; > > =20 > > if ((n =3D write(log_file, buf, n)) >=3D 0) > > @@ -238,8 +236,9 @@ void vlogmsg(bool newline, int pri, const char *for= mat, va_list ap) > > bool debug_print =3D (log_mask & LOG_MASK(LOG_DEBUG)) && log_file =3D= =3D -1; > > struct timespec tp; > > =20 > > + clock_gettime(CLOCK_MONOTONIC, &tp); >=20 > Maybe it's more readable now, but this has two disadvantages: >=20 > 1. this way, we call clock_gettime() also when it's not needed (that's > what I meant by "a bit of refactoring in vlogmsg()"). >=20 > If we log to the system logger, which is the default, we'll fetch a > timestamp for no reason, because the system logger adds it. Ah, true. Although I believe clock_gettime() is a vdso call which should be very cheap. > It's not that bad as we're not verbose in that case, so I'm actually > fine with this patch, but I wanted to point that out to you anyway, > first. >=20 > 2. POSIX.1-2024 has only one error defined for clock_gettime(): >=20 > The clock_gettime() function shall fail if: >=20 > [EOVERFLOW] > The number of seconds will not fit in an object of type time_t.= =20 >=20 > which should only happen on quite old systems (assuming their C > library even knows about clock_gettime()) in 2038 (assuming > CLOCK_REALTIME is used as initial CLOCK_MONOTONIC), but still, C > libraries often decide to add errors on their own, and we would > print stack contents if that happens. >=20 > Before this patch, that could only happen with --debug. Perhaps we > should simply initialise struct timespec to all zeroes (better to > print with the wrong timestamp than not printing at all) or to > log_start. Hm, true. >=20 > > + > > if (debug_print) { > > - clock_gettime(CLOCK_MONOTONIC, &tp); > > fprintf(stderr, logtime_fmt_and_arg(&tp)); > > fprintf(stderr, ": "); > > } > > @@ -249,7 +248,7 @@ void vlogmsg(bool newline, int pri, const char *for= mat, va_list ap) > > =20 > > va_copy(ap2, ap); /* Don't clobber ap, we need it again */ > > if (log_file !=3D -1) > > - logfile_write(newline, pri, format, ap2); > > + logfile_write(newline, pri, &tp, format, ap2); > > else if (!(log_mask & LOG_MASK(LOG_DEBUG))) > > passt_vsyslog(newline, pri, format, ap2); > > =20 >=20 --=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 --ekinU7TsSCkK8uMX Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIzBAEBCAAdFiEEO+dNsU4E3yXUXRK2zQJF27ox2GcFAmat4fkACgkQzQJF27ox 2GdUjBAAm8rbA8Z2bwv6Bj7noI6810G+mlslKutlSMmQ2h89kShhZGLJtqcy9+I8 WRtm80orAHSXwJ5P34HF5YuoQDIlDK9vx9zATwwTI4XxA22eHdsDMszX3ZoOWKZA Bnkw683ztrtFzF0u/XtxsZKu2W3+CJQ4J3awROO8oOMC/tLsj+NkVzQqyZxzUR9/ CyX4Gkl38MB6xvm8le6GF475XEMJ9w+vqZoeGCRreb8XE7zueayEar8Lp4L9uodv lfxYl9Ij+TCASP+EuxzzT+ZETH0krTVepAxygjji/Fd0LMkzJ6bxKO8nTobRWzXl 3yOQvQ77WJH4DPa6+7SCxPqZUMW1+gBW2rAlp/GVm+uzHDMMVTGNvrglCpid5QHl d/KFlqx8ARH85gMPIswuXmg424koArZIqb7SlB/neTJ6sExerrP3VaQSr7sDFRVy errh3c/gbx46P1zUODOTGxJ4jVQRaLUppLdCYe2gdVclnHBjjm3c5lnsu/KA7sni Sj87Y9jyMIqudyVuyRub2XMes0nA5iy82B0SZ3W41fvlm05+vcfanes5HwjSYhIh Q6a+d+MqCe0s3rSRtKwW7ra3ZuMGfAag4WI9wDWeand6rLRzOjtANc4wrJ8Cz4CW 1qM4Tq5kaZkiQyZsXH5GGJyhJZ0J37znI3g4V6DJTPLdsNSevqI= =lwuK -----END PGP SIGNATURE----- --ekinU7TsSCkK8uMX--