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
