[PATCH] 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 just 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.
Signed-off-by: Stefano Brivio
On Fri, Feb 02, 2024 at 12:32:57AM +0100, Stefano Brivio wrote:
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 just 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.
Signed-off-by: Stefano Brivio
The basic idea looks fine to me, but there's a curly edge case. At present vlogmsg() works ok before __openlog(), sending the message to stderr. We rely on this because there are die() calls before our __openlog(), which go via err() -> vlogmsg(). With this change, before the first __setlogmask(), which occurs right after the __openlog() then log_mask is initialized to zero. Which means, AFAICT, that we'll suppress all error messages before that point, which isn't great.
--- log.c | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/log.c b/log.c index 4a70e29..a66ecb7 100644 --- a/log.c +++ b/log.c @@ -45,33 +45,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)) +#define BEFORE_DAEMON (log_mask == LOG_MASK(LOG_EMERG))
void vlogmsg(int pri, const char *format, va_list ap) { FILE *out = log_to_stdout ? stdout : stderr; struct timespec tp;
- if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) { + if (log_mask & LOG_MASK(LOG_DEBUG) && log_file == -1) { 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))) || BEFORE_DAEMON) { 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) || + if ((log_mask & LOG_MASK(LOG_DEBUG) && log_file == -1) || (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) { (void)vfprintf(out, format, ap); if (format[strlen(format)] != '\n')
-- David Gibson | 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, 2 Feb 2024 12:02:19 +1100
David Gibson
On Fri, Feb 02, 2024 at 12:32:57AM +0100, Stefano Brivio wrote:
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 just 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.
Signed-off-by: Stefano Brivio
The basic idea looks fine to me, but there's a curly edge case. At present vlogmsg() works ok before __openlog(), sending the message to stderr. We rely on this because there are die() calls before our __openlog(), which go via err() -> vlogmsg().
With this change, before the first __setlogmask(), which occurs right after the __openlog() then log_mask is initialized to zero. Which means, AFAICT, that we'll suppress all error messages before that point, which isn't great.
Oops, right, thanks for pointing this out. I had a vague memory of some side benefit of setlogmask(0) with this regard but I couldn't really remember and gave up on it -- it was exactly this. I'm re-posting this with a static initialisation of log_mask now. -- Stefano
participants (2)
-
David Gibson
-
Stefano Brivio