[PATCH 0/3] Fixes for log timestamps

[PATCH 0/3] Fixes for log timestamps

[Stefano Brivio]

Taken out of the "Minor assorted fixes, mostly logging and tests"
series I recently posted.

Stefano Brivio (3):
  log, util: Fix sub-second part in relative log time calculation
  log: Initialise timestamp for relative log time also if we use a log
    file
  log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIME

 log.c   | 46 +++++++++++++++++++++++-----------------------
 log.h   |  1 +
 passt.c |  2 ++
 util.c  | 25 ++++++++++++++++++-------
 util.h  |  1 +
 5 files changed, 45 insertions(+), 30 deletions(-)

-- 
2.43.0

[PATCH 1/3] log, util: Fix sub-second part in relative log time calculation

[Stefano Brivio]

For some reason, in commit 01efc71ddd25 ("log, conf: Add support for
logging to file"), I added calculations for relative logging
timestamps using the difference for the seconds part only, not for
accounting for the fractional part.

Fix that by storing the initial timestamp, log_start, as a timespec
struct, and by calculating the difference from the starting time. Do
this in a macro as we need the same format in a few places.

To calculate the difference, turn the existing timespec_diff_ms() to
microseconds, timespec_diff_us(), and rewrite timespec_diff_ms() to
use that.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
---
 log.c  | 42 ++++++++++++++++++++++--------------------
 util.c | 25 ++++++++++++++++++-------
 util.h |  1 +
 3 files changed, 41 insertions(+), 27 deletions(-)

diff --git a/log.c b/log.c
index 54483e7..32157a8 100644
--- a/log.c
+++ b/log.c
@@ -40,12 +40,21 @@ static size_t	log_written;		/* Currently used bytes in log file */
 static size_t	log_cut_size;		/* Bytes to cut at start on rotation */
 static char	log_header[BUFSIZ];	/* File header, written back on cuts */
 
-static time_t	log_start;		/* Start timestamp */
+static struct timespec log_start;	/* Start timestamp */
 
 int		log_trace;		/* --trace mode enabled */
 bool		log_conf_parsed;	/* Logging options already parsed */
 bool		log_runtime;		/* Daemonised, or ready in foreground */
 
+/**
+ * logtime_fmt_and_arg() - Build format and arguments to print relative log time
+ * @x:		Current timestamp
+ */
+#define logtime_fmt_and_arg(x)						\
+	"%lli.%04lli",							\
+	(timespec_diff_us((x), &log_start) / 1000000LL),		\
+	(timespec_diff_us((x), &log_start) / 100LL)
+
 /**
  * vlogmsg() - Print or send messages to log or output files as configured
  * @newline:	Append newline at the end of the message, if missing
@@ -60,9 +69,8 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
 
 	if (debug_print) {
 		clock_gettime(CLOCK_REALTIME, &tp);
-		fprintf(stderr, "%lli.%04lli: ",
-			(long long int)tp.tv_sec - log_start,
-			(long long int)tp.tv_nsec / (100L * 1000));
+		fprintf(stderr, logtime_fmt_and_arg(&tp));
+		fprintf(stderr, ": ");
 	}
 
 	if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) {
@@ -144,12 +152,9 @@ void trace_init(int enable)
  */
 void __openlog(const char *ident, int option, int facility)
 {
-	struct timespec tp;
-
 	(void)option;
 
-	clock_gettime(CLOCK_REALTIME, &tp);
-	log_start = tp.tv_sec;
+	clock_gettime(CLOCK_REALTIME, &log_start);
 
 	if (log_sock < 0) {
 		struct sockaddr_un a = { .sun_family = AF_UNIX, };
@@ -255,10 +260,8 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now)
 	if (read(fd, buf, BUFSIZ) == -1)
 		return;
 
-	n = snprintf(buf, BUFSIZ,
-		     "%s - log truncated at %lli.%04lli", log_header,
-		     (long long int)(now->tv_sec - log_start),
-		     (long long int)(now->tv_nsec / (100L * 1000)));
+	n =  snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header);
+	n += snprintf(buf + n, BUFSIZ - n, logtime_fmt_and_arg(now));
 
 	/* Avoid partial lines by padding the header with spaces */
 	nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1);
@@ -288,10 +291,11 @@ static void logfile_rotate_move(int fd, const struct timespec *now)
 	char buf[BUFSIZ];
 	const char *nl;
 
-	header_len = snprintf(buf, BUFSIZ,
-			      "%s - log truncated at %lli.%04lli\n", log_header,
-			      (long long int)(now->tv_sec - log_start),
-			      (long long int)(now->tv_nsec / (100L * 1000)));
+	header_len =  snprintf(buf, BUFSIZ, "%s - log truncated at ",
+			       log_header);
+	header_len += snprintf(buf + header_len, BUFSIZ - header_len,
+			       logtime_fmt_and_arg(now));
+
 	if (lseek(fd, 0, SEEK_SET) == -1)
 		return;
 	if (write(fd, buf, header_len) == -1)
@@ -383,10 +387,8 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
 	if (clock_gettime(CLOCK_REALTIME, &now))
 		return;
 
-	n = snprintf(buf, BUFSIZ, "%lli.%04lli: %s",
-		     (long long int)(now.tv_sec - log_start),
-		     (long long int)(now.tv_nsec / (100L * 1000)),
-		     logfile_prefix[pri]);
+	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
+	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
 
 	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
 
diff --git a/util.c b/util.c
index c275b14..f2e26a7 100644
--- a/util.c
+++ b/util.c
@@ -239,6 +239,23 @@ void sock_probe_mem(struct ctx *c)
 	close(s);
 }
 
+/**
+ * timespec_diff_us() - Report difference in microseconds between two timestamps
+ * @a:		Minuend timestamp
+ * @b:		Subtrahend timestamp
+ *
+ * Return: difference in microseconds (wraps after 2^64 / 10^6s ~= 585k years)
+ */
+long long timespec_diff_us(const struct timespec *a, const struct timespec *b)
+{
+	if (a->tv_nsec < b->tv_nsec) {
+		return (b->tv_nsec - a->tv_nsec) / 1000 +
+		       (a->tv_sec - b->tv_sec - 1) * 1000000;
+	}
+
+	return (a->tv_nsec - b->tv_nsec) / 1000 +
+	       (a->tv_sec - b->tv_sec) * 1000000;
+}
 
 /**
  * timespec_diff_ms() - Report difference in milliseconds between two timestamps
@@ -249,13 +266,7 @@ void sock_probe_mem(struct ctx *c)
  */
 long timespec_diff_ms(const struct timespec *a, const struct timespec *b)
 {
-	if (a->tv_nsec < b->tv_nsec) {
-		return (b->tv_nsec - a->tv_nsec) / 1000000 +
-		       (a->tv_sec - b->tv_sec - 1) * 1000;
-	}
-
-	return (a->tv_nsec - b->tv_nsec) / 1000000 +
-	       (a->tv_sec - b->tv_sec) * 1000;
+	return timespec_diff_us(a, b) / 1000;
 }
 
 /**
diff --git a/util.h b/util.h
index 826614c..6f44eab 100644
--- a/util.h
+++ b/util.h
@@ -152,6 +152,7 @@ int sock_l4(const struct ctx *c, sa_family_t af, enum epoll_type type,
 	    uint32_t data);
 void sock_probe_mem(struct ctx *c);
 long timespec_diff_ms(const struct timespec *a, const struct timespec *b);
+long long timespec_diff_us(const struct timespec *a, const struct timespec *b);
 void bitmap_set(uint8_t *map, unsigned bit);
 void bitmap_clear(uint8_t *map, unsigned bit);
 bool bitmap_isset(const uint8_t *map, unsigned bit);
-- 
@@ -152,6 +152,7 @@ int sock_l4(const struct ctx *c, sa_family_t af, enum epoll_type type,
 	    uint32_t data);
 void sock_probe_mem(struct ctx *c);
 long timespec_diff_ms(const struct timespec *a, const struct timespec *b);
+long long timespec_diff_us(const struct timespec *a, const struct timespec *b);
 void bitmap_set(uint8_t *map, unsigned bit);
 void bitmap_clear(uint8_t *map, unsigned bit);
 bool bitmap_isset(const uint8_t *map, unsigned bit);
-- 
2.43.0

[PATCH 2/3] log: Initialise timestamp for relative log time also if we use a log file

[Stefano Brivio]

...not just for debug messages. Otherwise, timestamps in the log file
are consistent but the starting point is not zero.

Do this right away as we enter main(), so that the resulting
timestamps are as closely as possible relative to when we start.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 log.c   | 4 +---
 log.h   | 1 +
 passt.c | 2 ++
 3 files changed, 4 insertions(+), 3 deletions(-)

diff --git a/log.c b/log.c
index 32157a8..9474bad 100644
--- a/log.c
+++ b/log.c
@@ -40,7 +40,7 @@ static size_t	log_written;		/* Currently used bytes in log file */
 static size_t	log_cut_size;		/* Bytes to cut at start on rotation */
 static char	log_header[BUFSIZ];	/* File header, written back on cuts */
 
-static struct timespec log_start;	/* Start timestamp */
+struct timespec	log_start;		/* Start timestamp */
 
 int		log_trace;		/* --trace mode enabled */
 bool		log_conf_parsed;	/* Logging options already parsed */
@@ -154,8 +154,6 @@ void __openlog(const char *ident, int option, int facility)
 {
 	(void)option;
 
-	clock_gettime(CLOCK_REALTIME, &log_start);
-
 	if (log_sock < 0) {
 		struct sockaddr_un a = { .sun_family = AF_UNIX, };
 
diff --git a/log.h b/log.h
index 51ddafa..e03199c 100644
--- a/log.h
+++ b/log.h
@@ -44,6 +44,7 @@ void logmsg_perror(int pri, const char *format, ...)
 extern int log_trace;
 extern bool log_conf_parsed;
 extern bool log_runtime;
+extern struct timespec log_start;
 
 void trace_init(int enable);
 #define trace(...)							\
diff --git a/passt.c b/passt.c
index eed74ec..72ad704 100644
--- a/passt.c
+++ b/passt.c
@@ -207,6 +207,8 @@ int main(int argc, char **argv)
 	struct timespec now;
 	struct sigaction sa;
 
+	clock_gettime(CLOCK_REALTIME, &log_start);
+
 	arch_avx2_exec(argv);
 
 	isolate_initial();
-- 
@@ -207,6 +207,8 @@ int main(int argc, char **argv)
 	struct timespec now;
 	struct sigaction sa;
 
+	clock_gettime(CLOCK_REALTIME, &log_start);
+
 	arch_avx2_exec(argv);
 
 	isolate_initial();
-- 
2.43.0

[PATCH 3/3] log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIME

[Stefano Brivio]

We report relative timestamps in logs, so we want to avoid jumps in
the system time.

Suggested-by: David Gibson <david@gibson.dropbear.id.au>
Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
---
 log.c   | 4 ++--
 passt.c | 2 +-
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/log.c b/log.c
index 9474bad..0fb25b7 100644
--- a/log.c
+++ b/log.c
@@ -68,7 +68,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
 	struct timespec tp;
 
 	if (debug_print) {
-		clock_gettime(CLOCK_REALTIME, &tp);
+		clock_gettime(CLOCK_MONOTONIC, &tp);
 		fprintf(stderr, logtime_fmt_and_arg(&tp));
 		fprintf(stderr, ": ");
 	}
@@ -382,7 +382,7 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
 	char buf[BUFSIZ];
 	int n;
 
-	if (clock_gettime(CLOCK_REALTIME, &now))
+	if (clock_gettime(CLOCK_MONOTONIC, &now))
 		return;
 
 	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
diff --git a/passt.c b/passt.c
index 72ad704..6401730 100644
--- a/passt.c
+++ b/passt.c
@@ -207,7 +207,7 @@ int main(int argc, char **argv)
 	struct timespec now;
 	struct sigaction sa;
 
-	clock_gettime(CLOCK_REALTIME, &log_start);
+	clock_gettime(CLOCK_MONOTONIC, &log_start);
 
 	arch_avx2_exec(argv);
 
-- 
@@ -207,7 +207,7 @@ int main(int argc, char **argv)
 	struct timespec now;
 	struct sigaction sa;
 
-	clock_gettime(CLOCK_REALTIME, &log_start);
+	clock_gettime(CLOCK_MONOTONIC, &log_start);
 
 	arch_avx2_exec(argv);
 
-- 
2.43.0

Re: [PATCH 1/3] log, util: Fix sub-second part in relative log time calculation

[David Gibson]

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

On Thu, Jul 25, 2024 at 06:26:32PM +0200, Stefano Brivio wrote:
> For some reason, in commit 01efc71ddd25 ("log, conf: Add support for
> logging to file"), I added calculations for relative logging
> timestamps using the difference for the seconds part only, not for
> accounting for the fractional part.
> 
> Fix that by storing the initial timestamp, log_start, as a timespec
> struct, and by calculating the difference from the starting time. Do
> this in a macro as we need the same format in a few places.
> 
> To calculate the difference, turn the existing timespec_diff_ms() to
> microseconds, timespec_diff_us(), and rewrite timespec_diff_ms() to
> use that.
> 
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

> ---
>  log.c  | 42 ++++++++++++++++++++++--------------------
>  util.c | 25 ++++++++++++++++++-------
>  util.h |  1 +
>  3 files changed, 41 insertions(+), 27 deletions(-)
> 
> diff --git a/log.c b/log.c
> index 54483e7..32157a8 100644
> --- a/log.c
> +++ b/log.c
> @@ -40,12 +40,21 @@ static size_t	log_written;		/* Currently used bytes in log file */
>  static size_t	log_cut_size;		/* Bytes to cut at start on rotation */
>  static char	log_header[BUFSIZ];	/* File header, written back on cuts */
>  
> -static time_t	log_start;		/* Start timestamp */
> +static struct timespec log_start;	/* Start timestamp */
>  
>  int		log_trace;		/* --trace mode enabled */
>  bool		log_conf_parsed;	/* Logging options already parsed */
>  bool		log_runtime;		/* Daemonised, or ready in foreground */
>  
> +/**
> + * logtime_fmt_and_arg() - Build format and arguments to print relative log time
> + * @x:		Current timestamp
> + */
> +#define logtime_fmt_and_arg(x)						\
> +	"%lli.%04lli",							\
> +	(timespec_diff_us((x), &log_start) / 1000000LL),		\
> +	(timespec_diff_us((x), &log_start) / 100LL)
> +
>  /**
>   * vlogmsg() - Print or send messages to log or output files as configured
>   * @newline:	Append newline at the end of the message, if missing
> @@ -60,9 +69,8 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
>  
>  	if (debug_print) {
>  		clock_gettime(CLOCK_REALTIME, &tp);
> -		fprintf(stderr, "%lli.%04lli: ",
> -			(long long int)tp.tv_sec - log_start,
> -			(long long int)tp.tv_nsec / (100L * 1000));
> +		fprintf(stderr, logtime_fmt_and_arg(&tp));
> +		fprintf(stderr, ": ");
>  	}
>  
>  	if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) {
> @@ -144,12 +152,9 @@ void trace_init(int enable)
>   */
>  void __openlog(const char *ident, int option, int facility)
>  {
> -	struct timespec tp;
> -
>  	(void)option;
>  
> -	clock_gettime(CLOCK_REALTIME, &tp);
> -	log_start = tp.tv_sec;
> +	clock_gettime(CLOCK_REALTIME, &log_start);
>  
>  	if (log_sock < 0) {
>  		struct sockaddr_un a = { .sun_family = AF_UNIX, };
> @@ -255,10 +260,8 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now)
>  	if (read(fd, buf, BUFSIZ) == -1)
>  		return;
>  
> -	n = snprintf(buf, BUFSIZ,
> -		     "%s - log truncated at %lli.%04lli", log_header,
> -		     (long long int)(now->tv_sec - log_start),
> -		     (long long int)(now->tv_nsec / (100L * 1000)));
> +	n =  snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header);
> +	n += snprintf(buf + n, BUFSIZ - n, logtime_fmt_and_arg(now));
>  
>  	/* Avoid partial lines by padding the header with spaces */
>  	nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1);
> @@ -288,10 +291,11 @@ static void logfile_rotate_move(int fd, const struct timespec *now)
>  	char buf[BUFSIZ];
>  	const char *nl;
>  
> -	header_len = snprintf(buf, BUFSIZ,
> -			      "%s - log truncated at %lli.%04lli\n", log_header,
> -			      (long long int)(now->tv_sec - log_start),
> -			      (long long int)(now->tv_nsec / (100L * 1000)));
> +	header_len =  snprintf(buf, BUFSIZ, "%s - log truncated at ",
> +			       log_header);
> +	header_len += snprintf(buf + header_len, BUFSIZ - header_len,
> +			       logtime_fmt_and_arg(now));
> +
>  	if (lseek(fd, 0, SEEK_SET) == -1)
>  		return;
>  	if (write(fd, buf, header_len) == -1)
> @@ -383,10 +387,8 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
>  	if (clock_gettime(CLOCK_REALTIME, &now))
>  		return;
>  
> -	n = snprintf(buf, BUFSIZ, "%lli.%04lli: %s",
> -		     (long long int)(now.tv_sec - log_start),
> -		     (long long int)(now.tv_nsec / (100L * 1000)),
> -		     logfile_prefix[pri]);
> +	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
> +	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
>  
>  	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
>  
> diff --git a/util.c b/util.c
> index c275b14..f2e26a7 100644
> --- a/util.c
> +++ b/util.c
> @@ -239,6 +239,23 @@ void sock_probe_mem(struct ctx *c)
>  	close(s);
>  }
>  
> +/**
> + * timespec_diff_us() - Report difference in microseconds between two timestamps
> + * @a:		Minuend timestamp
> + * @b:		Subtrahend timestamp
> + *
> + * Return: difference in microseconds (wraps after 2^64 / 10^6s ~= 585k years)
> + */
> +long long timespec_diff_us(const struct timespec *a, const struct timespec *b)
> +{
> +	if (a->tv_nsec < b->tv_nsec) {
> +		return (b->tv_nsec - a->tv_nsec) / 1000 +
> +		       (a->tv_sec - b->tv_sec - 1) * 1000000;
> +	}
> +
> +	return (a->tv_nsec - b->tv_nsec) / 1000 +
> +	       (a->tv_sec - b->tv_sec) * 1000000;
> +}
>  
>  /**
>   * timespec_diff_ms() - Report difference in milliseconds between two timestamps
> @@ -249,13 +266,7 @@ void sock_probe_mem(struct ctx *c)
>   */
>  long timespec_diff_ms(const struct timespec *a, const struct timespec *b)
>  {
> -	if (a->tv_nsec < b->tv_nsec) {
> -		return (b->tv_nsec - a->tv_nsec) / 1000000 +
> -		       (a->tv_sec - b->tv_sec - 1) * 1000;
> -	}
> -
> -	return (a->tv_nsec - b->tv_nsec) / 1000000 +
> -	       (a->tv_sec - b->tv_sec) * 1000;
> +	return timespec_diff_us(a, b) / 1000;
>  }
>  
>  /**
> diff --git a/util.h b/util.h
> index 826614c..6f44eab 100644
> --- a/util.h
> +++ b/util.h
> @@ -152,6 +152,7 @@ int sock_l4(const struct ctx *c, sa_family_t af, enum epoll_type type,
>  	    uint32_t data);
>  void sock_probe_mem(struct ctx *c);
>  long timespec_diff_ms(const struct timespec *a, const struct timespec *b);
> +long long timespec_diff_us(const struct timespec *a, const struct timespec *b);
>  void bitmap_set(uint8_t *map, unsigned bit);
>  void bitmap_clear(uint8_t *map, unsigned bit);
>  bool bitmap_isset(const uint8_t *map, unsigned bit);

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

Re: [PATCH 3/3] log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIME

[David Gibson]

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

On Thu, Jul 25, 2024 at 06:26:34PM +0200, Stefano Brivio wrote:
> We report relative timestamps in logs, so we want to avoid jumps in
> the system time.
> 
> Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

I noticed another pre-existing nit, though..

> ---
>  log.c   | 4 ++--
>  passt.c | 2 +-
>  2 files changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/log.c b/log.c
> index 9474bad..0fb25b7 100644
> --- a/log.c
> +++ b/log.c
> @@ -68,7 +68,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
>  	struct timespec tp;
>  
>  	if (debug_print) {
> -		clock_gettime(CLOCK_REALTIME, &tp);
> +		clock_gettime(CLOCK_MONOTONIC, &tp);
>  		fprintf(stderr, logtime_fmt_and_arg(&tp));
>  		fprintf(stderr, ": ");
>  	}
> @@ -382,7 +382,7 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
>  	char buf[BUFSIZ];
>  	int n;
>  
> -	if (clock_gettime(CLOCK_REALTIME, &now))
> +	if (clock_gettime(CLOCK_MONOTONIC, &now))

We have two separate calls to get the time for "this" message.  I
think this means under the right circumstances we could have
essentially the same message logged to different places with
(slightly) different times.  That seems needlessly confusing.  It
would be nice to have a single point at which we capture the time for
a single message.

>  		return;
>  
>  	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
> diff --git a/passt.c b/passt.c
> index 72ad704..6401730 100644
> --- a/passt.c
> +++ b/passt.c
> @@ -207,7 +207,7 @@ int main(int argc, char **argv)
>  	struct timespec now;
>  	struct sigaction sa;
>  
> -	clock_gettime(CLOCK_REALTIME, &log_start);
> +	clock_gettime(CLOCK_MONOTONIC, &log_start);
>  
>  	arch_avx2_exec(argv);
>  

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

Re: [PATCH 3/3] log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIME

[Stefano Brivio]

On Fri, 26 Jul 2024 09:15:59 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> On Thu, Jul 25, 2024 at 06:26:34PM +0200, Stefano Brivio wrote:
> > We report relative timestamps in logs, so we want to avoid jumps in
> > the system time.
> > 
> > Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> > Signed-off-by: Stefano Brivio <sbrivio@redhat.com>  
> 
> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
> 
> I noticed another pre-existing nit, though..
> 
> > ---
> >  log.c   | 4 ++--
> >  passt.c | 2 +-
> >  2 files changed, 3 insertions(+), 3 deletions(-)
> > 
> > diff --git a/log.c b/log.c
> > index 9474bad..0fb25b7 100644
> > --- a/log.c
> > +++ b/log.c
> > @@ -68,7 +68,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
> >  	struct timespec tp;
> >  
> >  	if (debug_print) {
> > -		clock_gettime(CLOCK_REALTIME, &tp);
> > +		clock_gettime(CLOCK_MONOTONIC, &tp);
> >  		fprintf(stderr, logtime_fmt_and_arg(&tp));
> >  		fprintf(stderr, ": ");
> >  	}
> > @@ -382,7 +382,7 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
> >  	char buf[BUFSIZ];
> >  	int n;
> >  
> > -	if (clock_gettime(CLOCK_REALTIME, &now))
> > +	if (clock_gettime(CLOCK_MONOTONIC, &now))  
> 
> We have two separate calls to get the time for "this" message.  I
> think this means under the right circumstances we could have
> essentially the same message logged to different places with
> (slightly) different times.

This never happens because, in vlogmsg():

	bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;

> That seems needlessly confusing.  It would be nice to have a single
> point at which we capture the time for a single message.

...but yes, it might be confusing. A single clock_gettime() call would
need a bit of refactoring in vlogmsg().

-- 
Stefano

Re: [PATCH 3/3] log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIME

[David Gibson]

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

On Fri, Jul 26, 2024 at 11:32:57AM +0200, Stefano Brivio wrote:
> On Fri, 26 Jul 2024 09:15:59 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > On Thu, Jul 25, 2024 at 06:26:34PM +0200, Stefano Brivio wrote:
> > > We report relative timestamps in logs, so we want to avoid jumps in
> > > the system time.
> > > 
> > > Suggested-by: David Gibson <david@gibson.dropbear.id.au>
> > > Signed-off-by: Stefano Brivio <sbrivio@redhat.com>  
> > 
> > Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
> > 
> > I noticed another pre-existing nit, though..
> > 
> > > ---
> > >  log.c   | 4 ++--
> > >  passt.c | 2 +-
> > >  2 files changed, 3 insertions(+), 3 deletions(-)
> > > 
> > > diff --git a/log.c b/log.c
> > > index 9474bad..0fb25b7 100644
> > > --- a/log.c
> > > +++ b/log.c
> > > @@ -68,7 +68,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
> > >  	struct timespec tp;
> > >  
> > >  	if (debug_print) {
> > > -		clock_gettime(CLOCK_REALTIME, &tp);
> > > +		clock_gettime(CLOCK_MONOTONIC, &tp);
> > >  		fprintf(stderr, logtime_fmt_and_arg(&tp));
> > >  		fprintf(stderr, ": ");
> > >  	}
> > > @@ -382,7 +382,7 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
> > >  	char buf[BUFSIZ];
> > >  	int n;
> > >  
> > > -	if (clock_gettime(CLOCK_REALTIME, &now))
> > > +	if (clock_gettime(CLOCK_MONOTONIC, &now))  
> > 
> > We have two separate calls to get the time for "this" message.  I
> > think this means under the right circumstances we could have
> > essentially the same message logged to different places with
> > (slightly) different times.
> 
> This never happens because, in vlogmsg():
> 
> 	bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) &&
> 	log_file == -1;

Ah, good point.

> > That seems needlessly confusing.  It would be nice to have a single
> > point at which we capture the time for a single message.
> 
> ...but yes, it might be confusing. A single clock_gettime() call would
> need a bit of refactoring in vlogmsg().

I have a draft patch, I'll send soon.

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