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(a)gibson.dropbear.id.au> wrote:Ah, true. Although I believe clock_gettime() is a vdso call which should be very cheap.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(a)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.Hm, true.-- 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+ 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);