logs-show: move show_journal_by_unit _BOOT_ID match

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

diff --git a/src/shared/logs-show.c b/src/shared/logs-show.c
index 948bdb5ce9576993b296059f5849ec76b43d6306..a217c1e0810d91975e59ab19505b326ea54c0c44 100644 (file)
--- 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;