Back when that commit was made, didn't glibc cache the getpid() result in userspace? That would explain why it was not noticed.
On Fri, Jul 7, 2017, 23:18 <vcap...@pengaru.com> wrote: > In doing some casual journalctl profiling and stracing, it became apparent > that `journalctl -b --no-pager` runs across a significant quantity of logs, > ~10% of the time was thrown away on getpid() calls due to commmit a65f06b. > > As-is: > # time ./journalctl -b --no-pager > /dev/null > > real 0m11.033s > user 0m10.084s > sys 0m0.943s > > > After changing journal_pid_changed() to simply return 1: > # time ./journalctl -b --no-pager > /dev/null > > real 0m9.641s > user 0m9.449s > sys 0m0.191s > > > More system time is being expended in repeated getpid() calls than write(), > see the strace: > > 12:51:56.939287 write(1, "Jul 07 09:25:23 x61s unknown"..., 57) = 57 > <0.001276> > 12:51:56.940633 getpid() = 10713 <0.000032> > 12:51:56.940732 getpid() = 10713 <0.000012> > 12:51:56.940801 getpid() = 10713 <0.000032> > 12:51:56.940867 getpid() = 10713 <0.000041> > 12:51:56.940942 getpid() = 10713 <0.000041> > 12:51:56.941047 getpid() = 10713 <0.000012> > 12:51:56.941117 getpid() = 10713 <0.000012> > 12:51:56.941185 getpid() = 10713 <0.000011> > 12:51:56.941253 getpid() = 10713 <0.000011> > 12:51:56.941320 getpid() = 10713 <0.000039> > 12:51:56.941395 getpid() = 10713 <0.000041> > 12:51:56.941494 getpid() = 10713 <0.000011> > 12:51:56.941561 getpid() = 10713 <0.000012> > 12:51:56.941629 getpid() = 10713 <0.000039> > 12:51:56.942942 write(1, "Jul 07 09:25:23 x61s unknown"..., 57) = 57 > <0.000058> > 12:51:56.943052 getpid() = 10713 <0.000039> > 12:51:56.943156 getpid() = 10713 <0.000017> > 12:51:56.943230 getpid() = 10713 <0.000018> > 12:51:56.943305 getpid() = 10713 <0.000012> > 12:51:56.943374 getpid() = 10713 <0.000017> > 12:51:56.943449 getpid() = 10713 <0.000011> > 12:51:56.943517 getpid() = 10713 <0.000011> > 12:51:56.943585 getpid() = 10713 <0.000011> > 12:51:56.943652 getpid() = 10713 <0.000011> > 12:51:56.943721 getpid() = 10713 <0.000030> > 12:51:56.943796 getpid() = 10713 <0.000041> > 12:51:56.943870 getpid() = 10713 <0.000041> > 12:51:56.943944 getpid() = 10713 <0.000041> > 12:51:56.944061 getpid() = 10713 <0.001334> > 12:51:56.945459 write(1, "Jul 07 09:25:23 x61s unknown"..., 56) = 56 > <0.000018> > 12:51:56.945544 getpid() = 10713 <0.000017> > 12:51:56.945620 getpid() = 10713 <0.000017> > 12:51:56.945694 getpid() = 10713 <0.000012> > 12:51:56.945763 getpid() = 10713 <0.000011> > 12:51:56.945832 getpid() = 10713 <0.000012> > 12:51:56.945901 getpid() = 10713 <0.000011> > 12:51:56.945969 getpid() = 10713 <0.000011> > 12:51:56.946048 getpid() = 10713 <0.000013> > 12:51:56.946118 getpid() = 10713 <0.000024> > 12:51:56.946188 getpid() = 10713 <0.000047> > 12:51:56.946277 getpid() = 10713 <0.000041> > 12:51:56.946353 getpid() = 10713 <0.000041> > 12:51:56.946428 getpid() = 10713 <0.000040> > 12:51:56.946539 getpid() = 10713 <0.001363> > > As this is public sd-journal API, it's somewhat set in stone. However, > there's nothing preventing the systemd-internal tooling from linking with > a less defensive/conformant underlying implementation shared with the > public > API implementation where these kinds of overheads can be preserved. > > For the curious; the logs being processed for this boot are 48 * 8MiB on > SSD, > 1.8Ghz Core2 Duo, 4.12 kernel. > > Regards, > Vito Caputo > _______________________________________________ > systemd-devel mailing list > systemd-devel@lists.freedesktop.org > https://lists.freedesktop.org/mailman/listinfo/systemd-devel > -- Mantas Mikulėnas <graw...@gmail.com> Sent from my phone
_______________________________________________ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel