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 <sbrivio(a)redhat.com>
---
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')
--
2.39.2
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 <sbrivio(a)redhat.com>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 <david(a)gibson.dropbear.id.au> wrote:On Fri, Feb 02, 2024 at 12:32:57AM +0100, Stefano Brivio wrote: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. -- StefanoBefore 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 <sbrivio(a)redhat.com>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.