From 7ee4e172679029e54f44f096d2e0ec85905c79de Mon Sep 17 00:00:00 2001 From: Stefano Brivio Date: Fri, 2 Feb 2024 00:22:16 +0100 Subject: log: setlogmask(0) can actually result in a system call, don't use it Before commit 32d07f5e59f2 ("passt, pasta: Completely avoid dynamic memory allocation"), we didn't store the current log mask in a variable, and we fetched it using setlogmask(0) wherever needed. But after that commit, we can use our log_mask copy instead. And we should: with recent glibc versions, setlogmask(0) actually results in a system call, which causes a substantial overhead with high transfer rates: we use setlogmask(0) even to decide we don't want to print debug messages. Now that we rely on log_mask in early stages, before setlogmask() is called, we need to initialise that variable to the special LOG_EMERG mask value right away: define LOG_EARLY to make this clearer, and, while at it, group conditions in vlogmsg() into something more terse. Signed-off-by: Stefano Brivio Reviewed-by: David Gibson --- log.c | 18 ++++++++++-------- passt.c | 7 ++----- 2 files changed, 12 insertions(+), 13 deletions(-) diff --git a/log.c b/log.c index 4a70e29..eafaca2 100644 --- a/log.c +++ b/log.c @@ -30,9 +30,12 @@ #include "util.h" #include "passt.h" +/* LOG_EARLY means we don't know yet: log everything. LOG_EMERG is unused */ +#define LOG_EARLY LOG_MASK(LOG_EMERG) + static int log_sock = -1; /* Optional socket to system logger */ static char log_ident[BUFSIZ]; /* Identifier string for openlog() */ -static int log_mask; /* Current log priority mask */ +static int log_mask = LOG_EARLY; /* Current log priority mask */ static int log_opt; /* Options for openlog() */ static int log_file = -1; /* Optional log file descriptor */ @@ -45,34 +48,33 @@ static time_t log_start; /* Start timestamp */ int log_trace; /* --trace mode enabled */ int log_to_stdout; /* Print to stdout instead of stderr */ -#define BEFORE_DAEMON (setlogmask(0) == LOG_MASK(LOG_EMERG)) - void vlogmsg(int pri, const char *format, va_list ap) { + bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; + bool early_print = LOG_PRI(log_mask) == LOG_EARLY; FILE *out = log_to_stdout ? stdout : stderr; struct timespec tp; - if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) { + if (debug_print) { clock_gettime(CLOCK_REALTIME, &tp); fprintf(out, "%lli.%04lli: ", (long long int)tp.tv_sec - log_start, (long long int)tp.tv_nsec / (100L * 1000)); } - if ((LOG_MASK(LOG_PRI(pri)) & log_mask) || BEFORE_DAEMON) { + if ((log_mask & LOG_MASK(LOG_PRI(pri))) || early_print) { va_list ap2; va_copy(ap2, ap); /* Don't clobber ap, we need it again */ if (log_file != -1) logfile_write(pri, format, ap2); - else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG))) + else if (!(log_mask & LOG_MASK(LOG_DEBUG))) passt_vsyslog(pri, format, ap2); va_end(ap2); } - if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) || - (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) { + if (debug_print || (early_print && !(log_opt & LOG_PERROR))) { (void)vfprintf(out, format, ap); if (format[strlen(format)] != '\n') fprintf(out, "\n"); diff --git a/passt.c b/passt.c index 44d3a0b..aaa8e58 100644 --- a/passt.c +++ b/passt.c @@ -251,9 +251,6 @@ int main(int argc, char **argv) __openlog(log_name, 0, LOG_DAEMON); - /* Meaning we don't know yet: log everything. LOG_EMERG is unused */ - __setlogmask(LOG_MASK(LOG_EMERG)); - c.epollfd = epoll_create1(EPOLL_CLOEXEC); if (c.epollfd == -1) { perror("epoll_create1"); @@ -322,8 +319,8 @@ int main(int argc, char **argv) if (isolate_prefork(&c)) die("Failed to sandbox process, exiting"); - /* Once the log mask is not LOG_EMERG, we will no longer - * log to stderr if there was a log file specified. + /* Once the log mask is not LOG_EARLY, we will no longer log to stderr + * if there was a log file specified. */ if (c.debug) __setlogmask(LOG_UPTO(LOG_DEBUG)); -- cgit v1.2.3