[systemd-devel] Significant performance loss caused by commit a65f06b: journal: return -ECHILD after a fork

[Mantas Mikulėnas]

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 <vcaputo at 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 at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/systemd-devel
>
-- 

Mantas Mikulėnas <grawity at gmail.com>
Sent from my phone
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20170707/12c34b1e/attachment.html>