* [PATCH] log: setlogmask(0) can actually result in a system call, don't use it
@ 2024-02-01 23:32 Stefano Brivio
2024-02-02 1:02 ` David Gibson
0 siblings, 1 reply; 3+ messages in thread
From: Stefano Brivio @ 2024-02-01 23:32 UTC (permalink / raw)
To: passt-dev; +Cc: Laurent Vivier
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
^ permalink raw reply related [flat|nested] 3+ messages in thread
* Re: [PATCH] log: setlogmask(0) can actually result in a system call, don't use it
2024-02-01 23:32 [PATCH] log: setlogmask(0) can actually result in a system call, don't use it Stefano Brivio
@ 2024-02-02 1:02 ` David Gibson
2024-02-02 23:05 ` Stefano Brivio
0 siblings, 1 reply; 3+ messages in thread
From: David Gibson @ 2024-02-02 1:02 UTC (permalink / raw)
To: Stefano Brivio; +Cc: passt-dev, Laurent Vivier
[-- 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 --]
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [PATCH] log: setlogmask(0) can actually result in a system call, don't use it
2024-02-02 1:02 ` David Gibson
@ 2024-02-02 23:05 ` Stefano Brivio
0 siblings, 0 replies; 3+ messages in thread
From: Stefano Brivio @ 2024-02-02 23:05 UTC (permalink / raw)
To: David Gibson; +Cc: passt-dev, Laurent Vivier
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
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2024-02-02 23:06 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2024-02-01 23:32 [PATCH] log: setlogmask(0) can actually result in a system call, don't use it Stefano Brivio
2024-02-02 1:02 ` David Gibson
2024-02-02 23:05 ` Stefano Brivio
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).