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

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

[Stefano Brivio]

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@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')
-- 
@@ -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

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

[David Gibson]

[-- Attachment #1: Type: text/plain, Size: 3024 bytes --]

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@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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

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

[Stefano Brivio]

On Fri, 2 Feb 2024 12:02:19 +1100
David Gibson <david@gibson.dropbear.id.au> wrote:

> 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@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.

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