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

[PATCH v2] 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 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>
---
v2: Initialise log_mask so that prints before the first
    __setlogmask() call still work.

 log.c | 18 ++++++++++--------
 1 file changed, 10 insertions(+), 8 deletions(-)

diff --git a/log.c b/log.c
index 4a70e29..eafaca2 100644
--- a/log.c
+++ b/log.c
@@ -30,9 +30,12 @@
 #include "util.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 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_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_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)
 {
+	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;
 	struct timespec tp;
 
-	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) {
+	if (debug_print) {
 		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))) || early_print) {
 		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) ||
-	    (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) {
+	if (debug_print || (early_print && !(log_opt & LOG_PERROR))) {
 		(void)vfprintf(out, format, ap);
 		if (format[strlen(format)] != '\n')
 			fprintf(out, "\n");
-- 
@@ -30,9 +30,12 @@
 #include "util.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 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_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_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)
 {
+	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;
 	struct timespec tp;
 
-	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) {
+	if (debug_print) {
 		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))) || early_print) {
 		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) ||
-	    (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) {
+	if (debug_print || (early_print && !(log_opt & LOG_PERROR))) {
 		(void)vfprintf(out, format, ap);
 		if (format[strlen(format)] != '\n')
 			fprintf(out, "\n");
-- 
2.39.2

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

[David Gibson]

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

On Sat, Feb 03, 2024 at 12:06:01AM +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 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>

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