log: setlogmask(0) can actually result in a system call, don't use it

Before commit 32d07f5e59 ("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 <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
This commit is contained in:
Stefano Brivio 2024-02-02 00:22:16 +01:00
parent 78901eeae3
commit 7ee4e17267
2 changed files with 12 additions and 13 deletions

18
log.c
View file

@ -30,9 +30,12 @@
#include "util.h" #include "util.h"
#include "passt.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 int log_sock = -1; /* Optional socket to system logger */
static char log_ident[BUFSIZ]; /* Identifier string for openlog() */ 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_opt; /* Options for openlog() */
static int log_file = -1; /* Optional log file descriptor */ 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_trace; /* --trace mode enabled */
int log_to_stdout; /* Print to stdout instead of stderr */ 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) 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; FILE *out = log_to_stdout ? stdout : stderr;
struct timespec tp; struct timespec tp;
if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) { if (debug_print) {
clock_gettime(CLOCK_REALTIME, &tp); clock_gettime(CLOCK_REALTIME, &tp);
fprintf(out, "%lli.%04lli: ", fprintf(out, "%lli.%04lli: ",
(long long int)tp.tv_sec - log_start, (long long int)tp.tv_sec - log_start,
(long long int)tp.tv_nsec / (100L * 1000)); (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_list ap2;
va_copy(ap2, ap); /* Don't clobber ap, we need it again */ va_copy(ap2, ap); /* Don't clobber ap, we need it again */
if (log_file != -1) if (log_file != -1)
logfile_write(pri, format, ap2); 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); passt_vsyslog(pri, format, ap2);
va_end(ap2); va_end(ap2);
} }
if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) || if (debug_print || (early_print && !(log_opt & LOG_PERROR))) {
(BEFORE_DAEMON && !(log_opt & LOG_PERROR))) {
(void)vfprintf(out, format, ap); (void)vfprintf(out, format, ap);
if (format[strlen(format)] != '\n') if (format[strlen(format)] != '\n')
fprintf(out, "\n"); fprintf(out, "\n");

View file

@ -251,9 +251,6 @@ int main(int argc, char **argv)
__openlog(log_name, 0, LOG_DAEMON); __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); c.epollfd = epoll_create1(EPOLL_CLOEXEC);
if (c.epollfd == -1) { if (c.epollfd == -1) {
perror("epoll_create1"); perror("epoll_create1");
@ -322,8 +319,8 @@ int main(int argc, char **argv)
if (isolate_prefork(&c)) if (isolate_prefork(&c))
die("Failed to sandbox process, exiting"); die("Failed to sandbox process, exiting");
/* Once the log mask is not LOG_EMERG, we will no longer /* Once the log mask is not LOG_EARLY, we will no longer log to stderr
* log to stderr if there was a log file specified. * if there was a log file specified.
*/ */
if (c.debug) if (c.debug)
__setlogmask(LOG_UPTO(LOG_DEBUG)); __setlogmask(LOG_UPTO(LOG_DEBUG));