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
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(a)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);
--
2.43.0
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(a)redhat.com>Reviewed-by: David Gibson <david(a)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
...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(a)redhat.com>
Reviewed-by: David Gibson <david(a)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();
--
2.43.0
We report relative timestamps in logs, so we want to avoid jumps in
the system time.
Suggested-by: David Gibson <david(a)gibson.dropbear.id.au>
Signed-off-by: Stefano Brivio <sbrivio(a)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);
--
2.43.0
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(a)gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com>Reviewed-by: David Gibson <david(a)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
On Fri, 26 Jul 2024 09:15:59 +1000 David Gibson <david(a)gibson.dropbear.id.au> wrote:On Thu, Jul 25, 2024 at 06:26:34PM +0200, Stefano Brivio wrote:This never happens because, in vlogmsg(): bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;We report relative timestamps in logs, so we want to avoid jumps in the system time. Suggested-by: David Gibson <david(a)gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com>Reviewed-by: David Gibson <david(a)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....but yes, it might be confusing. A single clock_gettime() call would need a bit of refactoring in vlogmsg(). -- Stefano
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(a)gibson.dropbear.id.au> wrote:Ah, good point.On Thu, Jul 25, 2024 at 06:26:34PM +0200, Stefano Brivio wrote:This never happens because, in vlogmsg(): bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;We report relative timestamps in logs, so we want to avoid jumps in the system time. Suggested-by: David Gibson <david(a)gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com>Reviewed-by: David Gibson <david(a)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.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/~dgibsonThat 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().