From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from gandalf.ozlabs.org (mail.ozlabs.org [IPv6:2404:9400:2221:ea00::3]) by passt.top (Postfix) with ESMTPS id D9D215A0274 for ; Mon, 12 Feb 2024 03:45:38 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202312; t=1707705935; bh=/boTpqTpLwv9r3AxQpC++JMf4Hkl74+fzsy/yXpXTJY=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=PaMwKREZ52t+SB6gHMbRqV30lNYbr3AiIi67IZx2bHrisz8wsUSRPRtvAkKKOy+Vu NqupCjkhNPR2/GWKkY8CVZRlyYCBKYT/VAYSFW0VyRBK1ex0/kLL1GvJNz3dQvZWaa eiR2ef6clgcPcGRgB4Wy1wPa9Pr0W97sfx2+EXHpLNeR4BVHEWOobz5jRMTtZ99QZI Dvuy0t7Ws21pR8qJOrYKWYFTLS2EUTAI7AAiXKNHm3DNbhVfGSxavzseW58F8qChFA PGw2BJgiBcC8/QTnurGYcUujLnjRsEhAj1UUErAI4+Ofztt3qOdzAAehoZh1rBpljI DDoWce7SEMUEw== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4TY82l1Jksz4wyY; Mon, 12 Feb 2024 13:45:35 +1100 (AEDT) Date: Mon, 12 Feb 2024 13:45:30 +1100 From: David Gibson To: Stefano Brivio Subject: Re: [PATCH v3] log: setlogmask(0) can actually result in a system call, don't use it Message-ID: References: <20240211123839.905408-1-sbrivio@redhat.com> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="oV3JbNFgvmgkD2eF" Content-Disposition: inline In-Reply-To: <20240211123839.905408-1-sbrivio@redhat.com> Message-ID-Hash: BHFMPFUD5POBX2IGB2TJ7MHO6DWUYXI2 X-Message-ID-Hash: BHFMPFUD5POBX2IGB2TJ7MHO6DWUYXI2 X-MailFrom: dgibson@gandalf.ozlabs.org X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: passt-dev@passt.top X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: --oV3JbNFgvmgkD2eF Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable 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. >=20 > 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. >=20 > 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. >=20 > Signed-off-by: Stefano Brivio Reviewed-by: David Gibson > --- > v3: Include changes to passt.c I accidentally didn't commit in v2 >=20 > v2: Initialise log_mask so that prints before the first > __setlogmask() call still work. >=20 > log.c | 18 ++++++++++-------- > passt.c | 7 ++----- > 2 files changed, 12 insertions(+), 13 deletions(-) >=20 > 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" > =20 > +/* LOG_EARLY means we don't know yet: log everything. LOG_EMERG is unuse= d */ > +#define LOG_EARLY LOG_MASK(LOG_EMERG) > + > static int log_sock =3D -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 =3D LOG_EARLY; /* Current log priority mask */ > static int log_opt; /* Options for openlog() */ > =20 > static int log_file =3D -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 */ > =20 > -#define BEFORE_DAEMON (setlogmask(0) =3D=3D LOG_MASK(LOG_EMERG)) > - > void vlogmsg(int pri, const char *format, va_list ap) > { > + bool debug_print =3D (log_mask & LOG_MASK(LOG_DEBUG)) && log_file =3D= =3D -1; > + bool early_print =3D LOG_PRI(log_mask) =3D=3D LOG_EARLY; > FILE *out =3D log_to_stdout ? stdout : stderr; > struct timespec tp; > =20 > - if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file =3D=3D -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)); > } > =20 > - if ((LOG_MASK(LOG_PRI(pri)) & log_mask) || BEFORE_DAEMON) { > + if ((log_mask & LOG_MASK(LOG_PRI(pri))) || early_print) { > va_list ap2; > =20 > va_copy(ap2, ap); /* Don't clobber ap, we need it again */ > if (log_file !=3D -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); > =20 > va_end(ap2); > } > =20 > - if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file =3D=3D -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)] !=3D '\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) > =20 > __openlog(log_name, 0, LOG_DAEMON); > =20 > - /* Meaning we don't know yet: log everything. LOG_EMERG is unused */ > - __setlogmask(LOG_MASK(LOG_EMERG)); > - > c.epollfd =3D epoll_create1(EPOLL_CLOEXEC); > if (c.epollfd =3D=3D -1) { > perror("epoll_create1"); > @@ -322,8 +319,8 @@ int main(int argc, char **argv) > if (isolate_prefork(&c)) > die("Failed to sandbox process, exiting"); > =20 > - /* 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)); --=20 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 --oV3JbNFgvmgkD2eF Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIzBAEBCAAdFiEEO+dNsU4E3yXUXRK2zQJF27ox2GcFAmXJhkkACgkQzQJF27ox 2GcEhw/+NyuANYgeKbtrsmbheaA8EIx5DD+W/qxdynj2PEF/rGWQPUbUw32Pragj THho/7166POvntA1QKQYiVFdRpL6C17yNEL7MRZ4vs0pNKsHqAfv8SaW4IBh+n6D bVbCX8y0ckDwYsKZBNqq82lUyN/Qehl8KtQhya1Nt7L0SeFALstsgvgiVuzkz/Bq z6PVNNpjDT+quL7KvaD/8JDS8zp5klgRgGZVEC/qmNkhcyyGAZRB34VIjkCjqBa+ 6ZtnqUfX2v7VGVyLpj0DeqFsqmIVY1UKiMWXXir8gDO6P7e25/zJDtbwzvDDGpDu am4LWPiCpgHR6ijEo2e+roJulB41tLLLQzG2ZGDkTJlvWkxKjPh63QAwRKMj7kCd vHs7M4gEQSAcmkClC+ge5Fc+8AmmbwbnE4w8btaiciT8taId9+4LCPu4Or69qbhy kyG0su7xl07eU4jT+3fQYZQiULEewSn58jqXGyjOCsz7yOKVD/ZtOGgg3/G6IzYW 4NELozS/iAQUjSiZl2zZ4d6/s6SCAmxZA7SVScZ0IpKlJJ20YFpuZYysUMcpJtq9 kn67PdNep+TE0hYSgdurAfyGbS6GAyRqrPupM7H5fDbywJLUL4yFXt4j6lQzaCy8 NmvC/VmpBArp4fC7kWEhlQxKdZsYRTnX5x3wH/pW71lDYO6JJDk= =CX+R -----END PGP SIGNATURE----- --oV3JbNFgvmgkD2eF--