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

[Stefano Brivio <sbrivio@redhat.com>]

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.

   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.

> +
>  	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);
>  

-- 
Stefano