Re: [PATCH 2/2] log: Avoid duplicate calls to clock_gettime()

[David Gibson <david@gibson.dropbear.id.au>]

[-- Attachment #1: Type: text/plain, Size: 4856 bytes --]

On Mon, Jul 29, 2024 at 07:55:02PM +0200, Stefano Brivio wrote:
> On Mon, 29 Jul 2024 14:23:00 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > 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
> > 
> > These cases are mutually exclusive, so we don't ever print the same message
> > with different timestamps, but that's not particularly obvious to see.
> > 
> > Refactor to have a single clock_gettime() call in vlogmsg() and use it for
> > all the places we need it.
> > 
> > Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
> > ---
> >  log.c | 17 ++++++++---------
> >  1 file changed, 8 insertions(+), 9 deletions(-)
> > 
> > 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 timespec *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, va_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;
> >  
> > -	if (clock_gettime(CLOCK_MONOTONIC, &now))
> > -		return;
> > -
> > -	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
> > +	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp));
> >  	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
> >  
> >  	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
> > @@ -219,7 +217,7 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap)
> >  	if (newline && format[strlen(format)] != '\n')
> >  		n += snprintf(buf + n, BUFSIZ - n, "\n");
> >  
> > -	if ((log_written + n >= log_size) && logfile_rotate(log_file, &now))
> > +	if ((log_written + n >= log_size) && logfile_rotate(log_file, tp))
> >  		return;
> >  
> >  	if ((n = write(log_file, buf, n)) >= 0)
> > @@ -238,8 +236,9 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
> >  	bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;
> >  	struct timespec tp;
> >  
> > +	clock_gettime(CLOCK_MONOTONIC, &tp);
> 
> Maybe it's more readable now, but this has two disadvantages:
> 
> 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()").
> 
>    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.
> 
> 2. POSIX.1-2024 has only one error defined for clock_gettime():
> 
>     The clock_gettime() function shall fail if:
> 
>     [EOVERFLOW]
>         The number of seconds will not fit in an object of type time_t. 
> 
>    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.
> 
>    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.

> 
> > +
> >  	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 *format, va_list ap)
> >  
> >  		va_copy(ap2, ap); /* Don't clobber ap, we need it again */
> >  		if (log_file != -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);
> >  
> 

-- 
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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]