`systemctl status` (with journald access) seems unnecessarily slow (disk bound)

[sourcejedi]

Submission type

• Request for enhancement (RFE)

systemd version the issue has been seen with

236 git ish

Used distribution

Fedora 27

In case of bug report: Expected behaviour you didn't see

…

In case of bug report: Unexpected behaviour you saw

Using systemctl status, which shows the last five log messages, takes over 10 times longer than journalctl -b, which already shows all the same lines. This is particularly noticeable if you ask for several units; systemctl status *.mount takes 140x as long.

I think it would be better to optimize systemctl status, to explicitly not request messages from previous boots. IMO this would fit with the mental model of what systemctl status is supposed to do.

In case of bug report: Steps to reproduce the problem

$ time journalctl -b >/dev/null

real	0m0.101s
user	0m0.049s
sys	0m0.018s

$ time systemctl status dbus >/dev/null

real	0m4.670s
user	0m0.021s
sys	0m0.071s

$ time systemctl status *.mount>/dev/null

real	0m14.654s
user	0m0.075s
sys	0m0.214s

[bl33pbl0p]

Hmm, that's weird.

delta ~ $ time journalctl -b >/dev/null

real	0m0.329s
user	0m0.056s
sys	0m0.000s
delta ~ $ time systemctl status dbus > /dev/null

real	0m0.008s
user	0m0.003s
sys	0m0.002s
delta ~ $ time systemctl status *.mount>/dev/null

real	0m0.035s
user	0m0.005s
sys	0m0.013s

[sourcejedi]

Weird indeed! I have noticed this for a while, that systemctl status takes a few seconds to run.

Obviously my system has a persistent journal (i.e. saved across boots, and not just kept in the tmpfs /run/systemd/journal), and it has been around for some while.

du -ch /var/log/journal shows 1.2G. systemd-coredump isn't configured to dump into the journal, so surely it's all log messages...

ah, hum. It looks like it might be an unfortunate result of the crash logic, however that works. Also, this is on ext4, but I'm wondering if journald is preallocating excessively to avoid more btrfs woes.

$ du -ah /var/log/journal/ec36f0d290614a989246ce31e09df42e | sort -h | head
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@00055529c4b41469-5fa2261e52fef98b.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@00055529d2c9e916-6bf27f09ca0cc120.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@0005554f9468681b-0997a8af3c04e933.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@0005554fb7e6d845-8d89ed69c313e8c2.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@00055588d25afba3-f5f61491f3e02caa.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@000555b6e406fa5f-201c4199819347ce.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@000555dd78843b30-13361ece58800741.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@0005564159c8456d-6ca5c86b254b0390.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@000556e20ed8efdb-4c97262997a6c143.journal~
8.1M	/var/log/journal/ec36f0d290614a989246ce31e09df42e/system@000556e2fa5b5c76-50fba37e5d66c3f3.journal~
$ du -ah /var/log/journal/ec36f0d290614a989246ce31e09df42e|wc -l
101

[bl33pbl0p]

XFS here, disk usage currently is 304.0M, coredump logs backtraces to the journal here, so not entirely log messages, and the journal is indeed persistent.

17M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/user-1000@000561c8ff51f65e-9c409d5069741dce.journal~
17M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/user-1000@36d8cc8a7b1f4d1fac80068be50f07a0-00000000000004c1-000561c8ff4d0096.journal
25M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/system@000561c8fcbe39ec-a310bea3944a02d2.journal~
25M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/user-1000.journal
32M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/system@0005618a431687ed-c0e6fe776d47192b.journal~
81M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/system.journal
113M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/system@72510af5834c48c998a9088388519fb3-0000000000000001-000561c8fba14bd3.journal
305M	/var/log/journal/cabbd0ab8b7742b5a135974616f592a1/

[gdamjan]

it would make sense for systemctl status <service> to only show the logs from the current invocation (for running services) or from the last invocation for stopped services.

[sourcejedi]

If I use /usr/bin/time instead, I can see e.g. 73632 inputs (of 4096 byte pages, so ~290MB overall) causing a delay of 2.3s. This seems reasonable for large sequential IO on my hardware.

... and that was for journalctl -b -u <service>. It seems my problem is wider than just systemctl status. As in my previous transcript, this only happens the first time I look at <service>, but I can get the delay again by looking at a different service.

I think we actually already did what I suggested about systemctl status limiting it's output to the current boot.

systemd/src/shared/logs-show.c

Line 1453 in 7755083

r = add_match_this_boot(j, NULL);

Maybe I wasn't testing consistently... but it sounds as if -b -u <service> is actually working slower than plain -b. Or rather, each different -u <service> is having to load a whole lot of different data... sounds like some sort of index structure being loaded with some inefficiency? At least this is what's happening on my system.

[Self-Perfection]

I experience the same issue and I'd like to share some tests and measures that shed light to the issue.

The issue is disk bound. If all required data is stored in page cache systemctl status responds instantly. So some tools to work with page cache contents are required. I will use pcstat for decent measurement of how much of a given file is cached and cachedel from nocache to remove given files from page cache (alternatively one can echo 1 | tee /proc/sys/vm/drop_caches but this option clear all page cache and I wanted to avoid interference with rereading from disk anything that is not journal files).

First we need toolkit:

# Any service with frequent messages will do.
# co2mon used in my measures produces several messages per minute
SERVICE='co2mon.service'

# Display page cache statistics for 10 oldest journal files
oldest_files_cache_info() {
	pcstat $(ls --sort=time --reverse | head) |\
	perl -pe 'substr($_, 15, 55) = " ... "'
}

# Count total cached data size and count of uncached journal files
cache_stats() {
	# pcstat returns count of cached pages (4096 bytes) for each file
	pcstat -json=true *.journal |\
	jq 'reduce .[].cached as $item (0; . + $item) |
	. * 4096 / 1024 / 1024 | tostring | .[:6] |
	"Cached portion is: " + . + " MiB"'

	pcstat -json=true *.journal |\
	jq 'map(select(.cached == 0)) |	length | tostring |
	"Completely not cached files count: " + .'
}

clear_cache() {
	for f in *.journal; do cachedel "$f"; done
}

Start with looking around:

$ cd /var/log/journal/1*
$ du -h
2,7G    .
$ ls | wc -l
225
$ grep SystemMaxFileSize /etc/systemd/journald.conf
SystemMaxFileSize=16M
$ # Log directory contains almost 3 months of logs

Now real measurements

$ oldest_files_cache_info 
|-------------- ... -----------------+----------------+------------+-----------+---------|
| Name          ...                  | Size           | Pages      | Cached    | Percent |
|-------------- ... -----------------+----------------+------------+-----------+---------|
| user-1015.jou ...                  | 8388608        | 2048       | 74        | 003.613 |
| user-1017.jou ...                  | 8388608        | 2048       | 71        | 003.467 |
| user-1000@5a8 ... 79c004da.journal | 8388608        | 2048       | 101       | 004.932 |
| system@8650b4 ... 40ba6.journal    | 16777216       | 4096       | 499       | 012.183 |
| user-1000@5a8 ... ead87d2d.journal | 8388608        | 2048       | 71        | 003.467 |
| system@8650b4 ... 7e343.journal    | 16777216       | 4096       | 587       | 014.331 |
| system@8650b4 ... be3f7.journal    | 16777216       | 4096       | 1047      | 025.562 |
| user-1000@5a8 ... 2847c470.journal | 8388608        | 2048       | 117       | 005.713 |
| user-1000@5a8 ... 441014ea.journal | 8388608        | 2048       | 94        | 004.590 |
| system@8650b4 ... 52f06.journal    | 16777216       | 4096       | 419       | 010.229 |
|-------------- ... -----------------+----------------+------------+-----------+---------|
$ cache_stats
"Cached portion is: 212.21 MiB"
"Completely not cached files count: 0"
$ time systemctl status $SERVICE >/dev/null

real    0m0,030s
user    0m0,004s
sys     0m0,025s
$ #Now repeating test with empty cache
$ clear_cache 
$ cache_stats
"Cached portion is: 15.578 MiB"
"Completely not cached files count: 220"
$ time systemctl status $SERVICE >/dev/null

real    0m37,423s
user    0m0,014s
sys     0m0,322s
$ cache_stats
"Cached portion is: 1674.5 MiB"
"Completely not cached files count: 0"
$ oldest_files_cache_info 
|-------------- ... -----------------+----------------+------------+-----------+---------|
| Name          ...                  | Size           | Pages      | Cached    | Percent |
|-------------- ... -----------------+----------------+------------+-----------+---------|
| user-1015.jou ...                  | 8388608        | 2048       | 1024      | 050.000 |
| user-1017.jou ...                  | 8388608        | 2048       | 1024      | 050.000 |
| user-1000@5a8 ... 79c004da.journal | 8388608        | 2048       | 1024      | 050.000 |
| system@8650b4 ... 40ba6.journal    | 16777216       | 4096       | 2561      | 062.524 |
| user-1000@5a8 ... ead87d2d.journal | 8388608        | 2048       | 1024      | 050.000 |
| system@8650b4 ... 7e343.journal    | 16777216       | 4096       | 3292      | 080.371 |
| system@8650b4 ... be3f7.journal    | 16777216       | 4096       | 3623      | 088.452 |
| user-1000@5a8 ... 2847c470.journal | 8388608        | 2048       | 1024      | 050.000 |
| user-1000@5a8 ... 441014ea.journal | 8388608        | 2048       | 1024      | 050.000 |
| system@8650b4 ... 52f06.journal    | 16777216       | 4096       | 3103      | 075.757 |
|-------------- ... -----------------+----------------+------------+-----------+---------|

So what does it mean? systemctl status $SERVICE seems to show just 10 latest log events. My service gives plenty of logs, 10 messages are generated in less than a minute, so it should suffice to read just latest system.journal file to get all that is needed to print status. But systemctl status $SERVICE reads from every single journal file present! All 3 months of logs to show just events from latest minute!

systemd seems to be just broken in figuring out which journal files it has to parse and just reads from all files for every operation. So for comparison lets check past 3 days of journal (keep in mind, currently there are 200+ journal files for almost 3 months of logs). It should be enough to read only journal files that are newer than start date +1 file, but nope, journalctl reads everything:

$ clear_cache 
$ cache_stats
"Cached portion is: 16.195 MiB"
"Completely not cached files count: 220"
$ time journalctl --system --since=$(date +%F --date=-3day) _EXE=/usr/bin/sshd >/dev/null 

real    0m46,664s
user    0m0,023s
sys     0m0,488s
$ cache_stats
"Cached portion is: 1967.0 MiB"
"Completely not cached files count: 0"

[dtardon]

This is a duplicate of #2460.