[RFE] speedup journal export

[champtar]

While generating sos reports, journal exports takes pretty long Using journalctl --reverse we can get pretty significant speedups

# time sh -c "journalctl | tail -c 100m > /dev/null"
real    1m55.815s
user    1m48.612s
sys 0m7.896s

# time sh -c "journalctl --reverse | head -c 100m | tac > /dev/null"
real    0m8.674s
user    0m8.399s
sys 0m0.432s

# journalctl --disk-usage 
Archived and active journals take up 3.9G in the file system.

[jcastill]

Hi @champtar . I get the same or similar times when running in different RHELs and Fedoras, with different journal sizes. What can you tell us about the machine where these commands were run?

[pmoravec]

Innovative idea, I like that approach of thinking. Comparing it with the call flow of a command execution:

• we collect their outputs via https://github.com/sosreport/sos/blob/main/sos/report/plugins/__init__.py#L2346-L2351 (see sizelimit parameter there)
• we asynchronously wait for the execution at https://github.com/sosreport/sos/blob/main/sos/utilities.py#L282 - here we can't pass pipes in the commands
• so just for journalctl, we would have to "concatenate" individual commands (journalctl --reverse and head and tac) invoked via Popen (or use some different mechanism). And we would have to ensure this fragile concatenation will always work (there have been use cases where various commands get stuck in various ways and sos had to cope with that without getting stuck)

I am bit afraid most of implementations would suffer to their complexity or insufficient robustness due to above facts. If somebody does see some good implementation, I would be definitely interested in.

[jcastill]

Unless I'm mistaken, using tail or heads after calling journalctl will still load the whole file, which may be a waste. We have already --size, wouldn't that work better than having to use 'tail' or 'head' on the full file? Assuming that the time to capture the log is proportional to the size, we could capture the last 24 or 12 hours of logs and then apply size limits on top of that. In other words:

--all-logs gets everything, we don't need to filter. Normal execution without --all-logs: If journal log size is bigger than 1.5G (random number here, we can change it): capture last 24 hours of logs and apply size limit to 500M or whatever we decide. Else: capture the whole file.

[champtar]

@jcastill

I get the same or similar times when running in different RHELs and Fedoras, with different journal sizes. What can you tell us about the machine where these commands were run?

I'm extremely surprise by your results, my tests always show differences. This run was on an Alma 9.3 server, bare metal, SSD, XFS, but affinity limited to 1 core

Some other numbers (running each commands twice, showing the second run):

On a small Fedora 39 VPS ``` # time sh -c "journalctl | tail -c 100m > /dev/null" real 0m46,968s user 0m36,875s sys 0m9,878s # time sh -c "journalctl --reverse | head -c 100m | tac > /dev/null" real 0m18,551s user 0m14,397s sys 0m4,070s # journalctl --disk-usage Archived and active journals take up 886.7M in the file system. ``` On an 8 years old laptop, Fedora 39, SSD, encrypted disk, ext4 ``` $ time sh -c "journalctl | tail -c 100m > /dev/null" real 19m13,850s user 10m36,594s sys 8m33,288s $ time sh -c "journalctl --reverse | head -c 100m | tac > /dev/null" real 5m33,438s user 3m4,797s sys 2m28,186s $ journalctl --disk-usage Archived and active journals take up 1.3G in the file system. ``` On an old desktop acting as NAS, SSD, ``` # time sh -c "journalctl | tail -c 100m > /dev/null" real 10m21,551s user 5m0,823s sys 5m20,703s # time sh -c "journalctl --reverse | head -c 100m | tac > /dev/null" real 2m19,282s user 1m7,450s sys 1m12,177s # journalctl --disk-usage Archived and active journals take up 3.3G in the file system. ```

Unless I'm mistaken, using tail or heads after calling journalctl will still load the whole file

You are mistaken :) I don't know how --reverse is implemented, but head will close it stdin as soon as it reaches the limit, so journalctl will exit, thus it'll load only the latest journal chunks, not all of them. Using tail you must read everything from disk and decompress it, the difference can be huge.

@pmoravec

For the implementation, the quick and dirty way is to pass sh -c "journalctl --reverse | head -c 100m | tac as command, with also a suggested name

Right now sizelimit is doing a tail, keeping the whole output in memory, and if we timeout we have the earliest logs that might have been excluded with a larger timeout.

We could do it in 2 steps: 1) run journalctl --reverse with a head limit (using head or a python implementation), writing to a temp file 2) reverse the temp file (using tac or a python implementation)

If we timeout in step 1, we have the latest logs which is often what we want, and we don't need to have the full logs in memory at any point

[champtar]

I've played a bit with the journal cursor but it's slower (we need -n when using --cursor-file)

#!/bin/bash

cursor=$(mktemp cursor.XXXXXXXXXX)

logsize=0
while [ "$logsize" -lt 104857600 ]
do
  prevcursor="$(<$cursor)"
  ((logsize+=$(journalctl --reverse --cursor-file=$cursor -n 1000 | wc -c)))
  [ "$prevcursor" == "$(<$cursor)" ] && break
done

journalctl --cursor-file=$cursor

rm -f cursor

# time sh -c "journalctl --reverse | head -c 100m > sgol; tac sgol > logs; rm -f sgol"
real    0m8.526s
user    0m8.268s
sys 0m0.360s

# time ./export-journal.sh > logs
real    0m22.452s
user    0m18.495s
sys 0m4.524s