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

[David Gibson <david@gibson.dropbear.id.au>]

[-- 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 --]