[PATCH 0/2] Avoid duplicated clock_gettime() in logging
Remove a small nit in the logging code. David Gibson (2): log: Make logfile_write() private log: Avoid duplicate calls to clock_gettime() log.c | 344 +++++++++++++++++++++++++++++----------------------------- log.h | 1 - 2 files changed, 172 insertions(+), 173 deletions(-) -- 2.45.2
logfile_write() is not used outside log.c, nor should it be. It should
only be used externall via the general logging functions. Make it static
in log.c. To avoid forward declarations this requires moving a bunch of
functions earlier in the file.
Signed-off-by: David Gibson
On Mon, 29 Jul 2024 14:22:59 +1000
David Gibson
logfile_write() is not used outside log.c, nor should it be. It should only be used externall via the general logging functions. Make it static in log.c. To avoid forward declarations this requires moving a bunch of functions earlier in the file.
Signed-off-by: David Gibson
Applied (1/2 only, for the moment). -- Stefano
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
On Mon, 29 Jul 2024 14:23:00 +1000
David Gibson
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
--- 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
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: 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
--- 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
participants (2)
-
David Gibson
-
Stefano Brivio