From f82027042a6b4acb2aed8fa8010393df8fd12656 Mon Sep 17 00:00:00 2001 From: Vito Caputo Date: Mon, 26 Oct 2020 23:24:34 -0700 Subject: [PATCH] logs-show: move show_journal_by_unit _BOOT_ID match MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit In scrutinizing the journal overhead of `systemctl status $service` it became apparent that the matching engine was performing the unit matches on every journal in my system, even ones containing nothing relevant to the current boot. This seemed strange and likely suboptimal to me, since there's likely far more unit data to rifle through than boot IDs in any given journal. The _BOOT_ID match seemed like it should be serving as an early exit match on irrelevant journals, but that wasn't what seemed to be happening. As a quick experiment to see if I could get the _BOOT_ID match to be something along the lines of a higher priority when matching, and try early exit on these unrelated journals, I moved add_match_this_boot() to after the unit match adds, inserting a conjunction between them. The end result seems to be a very substantial performance gain in my simple uncached tests, and I still get the expected journal output from the `systemctl status $service` command: ---------------------------------------------------------------------- Unmodified systemctl times: root@localhost:/# echo 2 > /proc/sys/vm/drop_caches root@localhost:/# time systemctl --no-pager status dbus ● dbus.service - D-Bus System Message Bus Loaded: loaded (/lib/systemd/system/dbus.service; static; vendor preset: enabled) Active: active (running) since Sun 2020-10-25 17:03:05 PDT; 1 day 6h ago Docs: man:dbus-daemon(1) Main PID: 572 (dbus-daemon) Memory: 2.8M CPU: 110ms CGroup: /system.slice/dbus.service └─572 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation Oct 25 17:03:05 localhost systemd[1]: Started D-Bus System Message Bus. Oct 25 17:06:26 localhost dbus[572]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Oct 25 17:06:26 localhost dbus[572]: [system] Successfully activated service 'org.freedesktop.machine1' real 0m0.695s user 0m0.005s sys 0m0.043s root@localhost:/# echo 2 > /proc/sys/vm/drop_caches root@localhost:/# time systemctl --no-pager status dbus ● dbus.service - D-Bus System Message Bus Loaded: loaded (/lib/systemd/system/dbus.service; static; vendor preset: enabled) Active: active (running) since Sun 2020-10-25 17:03:05 PDT; 1 day 6h ago Docs: man:dbus-daemon(1) Main PID: 572 (dbus-daemon) Memory: 2.8M CPU: 110ms CGroup: /system.slice/dbus.service └─572 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation Oct 25 17:03:05 localhost systemd[1]: Started D-Bus System Message Bus. Oct 25 17:06:26 localhost dbus[572]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Oct 25 17:06:26 localhost dbus[572]: [system] Successfully activated service 'org.freedesktop.machine1' real 0m0.696s user 0m0.003s sys 0m0.046s root@localhost:/# echo 2 > /proc/sys/vm/drop_caches root@localhost:/# time systemctl --no-pager status dbus ● dbus.service - D-Bus System Message Bus Loaded: loaded (/lib/systemd/system/dbus.service; static; vendor preset: enabled) Active: active (running) since Sun 2020-10-25 17:03:05 PDT; 1 day 6h ago Docs: man:dbus-daemon(1) Main PID: 572 (dbus-daemon) Memory: 2.8M CPU: 110ms CGroup: /system.slice/dbus.service └─572 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation Oct 25 17:03:05 localhost systemd[1]: Started D-Bus System Message Bus. Oct 25 17:06:26 localhost dbus[572]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Oct 25 17:06:26 localhost dbus[572]: [system] Successfully activated service 'org.freedesktop.machine1' real 0m0.694s user 0m0.006s sys 0m0.041s ---------------------------------------------------------------------- Modified systemctl including this commit: root@localhost:/home/vc/gh/systemd/build# echo 2 > /proc/sys/vm/drop_caches root@localhost:/home/vc/gh/systemd/build# time ./systemctl --no-pager status dbus ● dbus.service - D-Bus System Message Bus Loaded: loaded (/lib/systemd/system/dbus.service; static) Active: active (running) since Sun 2020-10-25 17:03:05 PDT; 1 day 6h ago TriggeredBy: ● dbus.socket Docs: man:dbus-daemon(1) Main PID: 572 (dbus-daemon) Memory: 2.8M CPU: 110ms CGroup: /system.slice/dbus.service └─572 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation Oct 25 17:03:05 localhost systemd[1]: Started D-Bus System Message Bus. Oct 25 17:06:26 localhost dbus[572]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Oct 25 17:06:26 localhost dbus[572]: [system] Successfully activated service 'org.freedesktop.machine1' real 0m0.168s user 0m0.003s sys 0m0.016s root@localhost:/home/vc/gh/systemd/build# echo 2 > /proc/sys/vm/drop_caches root@localhost:/home/vc/gh/systemd/build# time ./systemctl --no-pager status dbus ● dbus.service - D-Bus System Message Bus Loaded: loaded (/lib/systemd/system/dbus.service; static) Active: active (running) since Sun 2020-10-25 17:03:05 PDT; 1 day 6h ago TriggeredBy: ● dbus.socket Docs: man:dbus-daemon(1) Main PID: 572 (dbus-daemon) Memory: 2.8M CPU: 110ms CGroup: /system.slice/dbus.service └─572 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation Oct 25 17:03:05 localhost systemd[1]: Started D-Bus System Message Bus. Oct 25 17:06:26 localhost dbus[572]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Oct 25 17:06:26 localhost dbus[572]: [system] Successfully activated service 'org.freedesktop.machine1' real 0m0.167s user 0m0.005s sys 0m0.013s root@localhost:/home/vc/gh/systemd/build# echo 2 > /proc/sys/vm/drop_caches root@localhost:/home/vc/gh/systemd/build# time ./systemctl --no-pager status dbus ● dbus.service - D-Bus System Message Bus Loaded: loaded (/lib/systemd/system/dbus.service; static) Active: active (running) since Sun 2020-10-25 17:03:05 PDT; 1 day 6h ago TriggeredBy: ● dbus.socket Docs: man:dbus-daemon(1) Main PID: 572 (dbus-daemon) Memory: 2.8M CPU: 110ms CGroup: /system.slice/dbus.service └─572 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation Oct 25 17:03:05 localhost systemd[1]: Started D-Bus System Message Bus. Oct 25 17:06:26 localhost dbus[572]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' Oct 25 17:06:26 localhost dbus[572]: [system] Successfully activated service 'org.freedesktop.machine1' real 0m0.170s user 0m0.005s sys 0m0.014s --- src/shared/logs-show.c | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/shared/logs-show.c b/src/shared/logs-show.c index 948bdb5ce9..a217c1e081 100644 --- a/src/shared/logs-show.c +++ b/src/shared/logs-show.c @@ -1635,10 +1635,6 @@ int show_journal_by_unit( if (r < 0) return log_error_errno(r, "Failed to open journal: %m"); - r = add_match_this_boot(j, NULL); - if (r < 0) - return r; - if (system_unit) r = add_matches_for_unit(j, unit); else @@ -1646,6 +1642,14 @@ int show_journal_by_unit( if (r < 0) return log_error_errno(r, "Failed to add unit matches: %m"); + r = sd_journal_add_conjunction(j); + if (r < 0) + return log_error_errno(r, "Failed to add conjunction: %m"); + + r = add_match_this_boot(j, NULL); + if (r < 0) + return r; + if (DEBUG_LOGGING) { _cleanup_free_ char *filter;