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

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

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