* [PATCH v3] log: setlogmask(0) can actually result in a system call, don't use it
@ 2024-02-11 12:38 Stefano Brivio
2024-02-12 2:45 ` David Gibson
0 siblings, 1 reply; 2+ messages in thread
From: Stefano Brivio @ 2024-02-11 12:38 UTC (permalink / raw)
To: passt-dev, David Gibson
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>
---
v3: Include changes to passt.c I accidentally didn't commit in v2
v2: Initialise log_mask so that prints before the first
__setlogmask() call still work.
log.c | 18 ++++++++++--------
passt.c | 7 ++-----
2 files changed, 12 insertions(+), 13 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");
diff --git a/passt.c b/passt.c
index 44d3a0b..aaa8e58 100644
--- a/passt.c
+++ b/passt.c
@@ -251,9 +251,6 @@ int main(int argc, char **argv)
__openlog(log_name, 0, LOG_DAEMON);
- /* Meaning we don't know yet: log everything. LOG_EMERG is unused */
- __setlogmask(LOG_MASK(LOG_EMERG));
-
c.epollfd = epoll_create1(EPOLL_CLOEXEC);
if (c.epollfd == -1) {
perror("epoll_create1");
@@ -322,8 +319,8 @@ int main(int argc, char **argv)
if (isolate_prefork(&c))
die("Failed to sandbox process, exiting");
- /* Once the log mask is not LOG_EMERG, we will no longer
- * log to stderr if there was a log file specified.
+ /* Once the log mask is not LOG_EARLY, we will no longer log to stderr
+ * if there was a log file specified.
*/
if (c.debug)
__setlogmask(LOG_UPTO(LOG_DEBUG));
--
@@ -251,9 +251,6 @@ int main(int argc, char **argv)
__openlog(log_name, 0, LOG_DAEMON);
- /* Meaning we don't know yet: log everything. LOG_EMERG is unused */
- __setlogmask(LOG_MASK(LOG_EMERG));
-
c.epollfd = epoll_create1(EPOLL_CLOEXEC);
if (c.epollfd == -1) {
perror("epoll_create1");
@@ -322,8 +319,8 @@ int main(int argc, char **argv)
if (isolate_prefork(&c))
die("Failed to sandbox process, exiting");
- /* Once the log mask is not LOG_EMERG, we will no longer
- * log to stderr if there was a log file specified.
+ /* Once the log mask is not LOG_EARLY, we will no longer log to stderr
+ * if there was a log file specified.
*/
if (c.debug)
__setlogmask(LOG_UPTO(LOG_DEBUG));
--
2.39.2
^ permalink raw reply related [flat|nested] 2+ messages in thread
* Re: [PATCH v3] log: setlogmask(0) can actually result in a system call, don't use it
2024-02-11 12:38 [PATCH v3] log: setlogmask(0) can actually result in a system call, don't use it Stefano Brivio
@ 2024-02-12 2:45 ` David Gibson
0 siblings, 0 replies; 2+ messages in thread
From: David Gibson @ 2024-02-12 2:45 UTC (permalink / raw)
To: Stefano Brivio; +Cc: passt-dev
[-- Attachment #1: Type: text/plain, Size: 4627 bytes --]
On Sun, Feb 11, 2024 at 01:38:39PM +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>
> ---
> v3: Include changes to passt.c I accidentally didn't commit in v2
>
> v2: Initialise log_mask so that prints before the first
> __setlogmask() call still work.
>
> log.c | 18 ++++++++++--------
> passt.c | 7 ++-----
> 2 files changed, 12 insertions(+), 13 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");
> diff --git a/passt.c b/passt.c
> index 44d3a0b..aaa8e58 100644
> --- a/passt.c
> +++ b/passt.c
> @@ -251,9 +251,6 @@ int main(int argc, char **argv)
>
> __openlog(log_name, 0, LOG_DAEMON);
>
> - /* Meaning we don't know yet: log everything. LOG_EMERG is unused */
> - __setlogmask(LOG_MASK(LOG_EMERG));
> -
> c.epollfd = epoll_create1(EPOLL_CLOEXEC);
> if (c.epollfd == -1) {
> perror("epoll_create1");
> @@ -322,8 +319,8 @@ int main(int argc, char **argv)
> if (isolate_prefork(&c))
> die("Failed to sandbox process, exiting");
>
> - /* Once the log mask is not LOG_EMERG, we will no longer
> - * log to stderr if there was a log file specified.
> + /* Once the log mask is not LOG_EARLY, we will no longer log to stderr
> + * if there was a log file specified.
> */
> if (c.debug)
> __setlogmask(LOG_UPTO(LOG_DEBUG));
--
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 --]
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2024-02-12 2:45 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2024-02-11 12:38 [PATCH v3] log: setlogmask(0) can actually result in a system call, don't use it Stefano Brivio
2024-02-12 2:45 ` David Gibson
Code repositories for project(s) associated with this public inbox
https://passt.top/passt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for IMAP folder(s).