[utilities,plugins] speedup journal collection (v2) #3879

champtar · 2024-12-13T04:59:47Z

Instead of generating all the logs and tailing the last 100M, we get the first 100M of 'journalctl --reverse' that we then reverse again using our own implementation of tac.

To handle multiline logs we would need to use "tac -brs '^[^ ]'" that takes ~30s on 100M of logs when plain 'tac' takes ~0.3s. Our simple implementation in python takes 0.7s, and avoid an extra dependency.

On journalctl timeout we now get the most recents logs.

During collection logs are now buffered on disk, so we use 2xsizelimit. While running our tac we could actually truncate the source file to limit disk usage. Previously buffering was in RAM (also 2xsizelimit).

On my test server, logs plugin runtime goes from 34s to 9.5s.

Fixes #3615

Please place an 'X' inside each '[]' to confirm you adhere to our Contributor Guidelines

Is the commit message split over multiple lines and hard-wrapped at 72 characters?
Is the subject and message clear and concise?
Does the subject start with [plugin_name] if submitting a plugin patch or a [section_name] if part of the core sosreport code?
Does the commit contain a Signed-off-by: First Lastname [email protected]?
Are any related Issues or existing PRs properly referenced via a Closes (Issue) or Resolved (PR) line?
Are all passwords or private data gathered by this PR obfuscated?

packit-as-a-service · 2024-12-13T05:02:30Z

Congratulations! One of the builds has completed. 🍾

You can install the built RPMs by following these steps:

sudo yum install -y dnf-plugins-core on RHEL 8
sudo dnf install -y dnf-plugins-core on Fedora
dnf copr enable packit/sosreport-sos-3879
And now you can install the packages.

Please note that the RPMs should be used only in a testing environment.

pmoravec · 2024-12-18T14:07:57Z

I can confirm VERY evident speedup on a tested RHEL8 system with:

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

where current upstream executes python3 bin/sos report -o logs --batch --build in 18s and this PR shrinks it to 3s.

Some test is failing - can you @champtar review it or do you need some help? I might get to the failure later today /tomorrow.

sos/report/plugins/__init__.py

champtar · 2024-12-18T14:53:39Z

I'm off until the 27th so no rush for the review, and I was thinking about even implementing 'head' in Python

pmoravec · 2024-12-18T14:56:00Z

tests/report_tests/plugin_tests/defaults.py:40:            if cmd['exec'] == 'journalctl --no-pager  --unit cups':

needs to be updated to reflect changed command exec "sh -c 'journalctl --no-pager --unit cups --reverse | head -c 104857600'" - I vote for 'journalctl --no-pager --unit cups' in cmd['exec'] test.

The 2-tests/report_tests/plugin_tests/logs.py:JournalSizeLimitTest.test_journal_tailed_and_linked failure: The PR breaks part of tailit functionality: when a command output is bigger than --log-size (or --journal-size here), sosreport looks like:

# ll /var/tmp/sosreport-pmoravec-rhel9-8675309-2024-12-18-dusvggk/sos_commands/logs/
total 24
-rw-r--r--. 1 root root    63 Dec 18 15:50 journalctl_--disk-usage
lrwxrwxrwx. 1 root root    51 Dec 18 15:50 journalctl_--no-pager -> ../../sos_strings/logs/journalctl_--no-pager.tailed
lrwxrwxrwx. 1 root root    58 Dec 18 15:50 journalctl_--no-pager_--boot -> ../../sos_strings/logs/journalctl_--no-pager_--boot.tailed
-rw-r--r--. 1 root root    82 Dec 18 15:50 journalctl_--no-pager_--boot_-1
-rw-r--r--. 1 root root 13355 Dec 18 15:50 ls_-alRh_.var.log
# ll /var/tmp/sosreport-pmoravec-rhel9-8675309-2024-12-18-dusvggk/sos_strings/logs/
total 24824
-rw-r--r--. 1 root root 10484923 Dec 18 15:50 journalctl_--no-pager_--boot.tailed
-rw-r--r--. 1 root root 10484923 Dec 18 15:50 journalctl_--no-pager.tailed
-rw-r--r--. 1 root root  4445393 Dec 18 15:50 var.log.messages-20241201.tailed
#

And manifest.json tracks that via "truncated": true,.

With this PR, I see:

# ll /var/tmp/sosreport-pmoravec-rhel9-8675309-2024-12-18-zagarel/sos_commands/logs/
total 20464
-rw-r--r--. 1 root root       63 Dec 18 15:50 journalctl_--disk-usage
-rw-r--r--. 1 root root 10460043 Dec 18 15:50 journalctl_--no-pager
-rw-r--r--. 1 root root 10460043 Dec 18 15:50 journalctl_--no-pager_--boot
-rw-r--r--. 1 root root       82 Dec 18 15:50 journalctl_--no-pager_--boot_-1
-rw-r--r--. 1 root root    22730 Dec 18 15:50 ls_-alZR_.var.log
#

That suggests the journalctl outputs are not truncated, which is misleading.

pmoravec · 2025-01-19T08:45:31Z

Hi @arif-ali and @TurboTurtle , is this approach worth to try? My answer is "carefully yes".

Hi @champtar , do you need some help with updating the tests?

sos/utilities.py

pmoravec · 2025-01-31T08:41:01Z

sos/utilities.py

+                        )
+                    else:
+                        # pylint: disable=consider-using-with
+                        _output = open(to_file, 'wb')


Ditto - why binary mode for tac=False?

champtar · 2025-01-26T04:32:10Z

@pmoravec cirrus-ci is broken right now, but this should be ready for review

sos/utilities.py

pmoravec · 2025-01-29T09:02:37Z

Thanks for the new push. CI jobs restarted, seems good. I review the code now, will test functionality later (today or tomorrow, I assume).

sos/utilities.py

champtar · 2025-01-30T04:17:53Z

Not in the PR, but I was thinking about making TailReader work with to_file at some point, as I think we don't use the 'output' that often

pmoravec · 2025-01-30T21:07:56Z

So far the PR survived various my corner-case tests I invented. I shall review the code tomorrow..

sos/utilities.py

pmoravec · 2025-01-31T21:34:07Z

All up to one nitpick is good. I confirm great performance gain (and no visible performance penalty for journals having 100MB where the new approach additionally has to tac the data). Several corner cases checked, no issue found. Code seems good.

I like the idea, but would welcome another profound review of others as well - since we touch a frequently used code.

tac_logs() reverses the order of the logs in a text file but keeps multiline logs in order. It is aimed at reversing 'journalctl --reverse'. This avoids depending on GNU coreutils version of tac (busybox tac is missing some flags) and is way faster. Testing with 100MB of logs: - tac -brs '^[^ ]' (handle multiline): ~30s - tac_logs (our python implementation): ~0.7s - tac (not handling multiline logs): ~0.3s If we are concerned about disk usage, we could call mmap.resize() to truncate the input file while processing. Signed-off-by: Etienne Champetier <[email protected]>

We are going to introduce HeadReader. Signed-off-by: Etienne Champetier <[email protected]>

Will be used to keep the first sizelimit MB from a program stdout. Signed-off-by: Etienne Champetier <[email protected]>

Using sizelimit with to_file now keep the start of the command output instead of being ignored. You can use tac with and without sizelimit. Signed-off-by: Etienne Champetier <[email protected]>

Instead of generating all the logs and tailing the last 100M, we get the first 100M of 'journalctl --reverse' that we then reverse again using tac_logs(). On journalctl timeout we now get the most recents logs where previously we were getting some random old logs. During collection, logs are now buffered on disk, so we use 2xsizelimit. Previously buffering was in RAM (also 2xsizelimit). On my test server, logs plugin runtime goes from 34s to 9.5s. Signed-off-by: Etienne Champetier <[email protected]>

pmoravec · 2025-02-01T14:50:04Z

I rerun the failed test - it should succeed, I rather smell some infra issue (and logs dont show any reason).

champtar · 2025-02-01T20:10:43Z

Thanks for the review @pmoravec !

pmoravec

Maybe it makes sense to squash some commits, but I am ok also with this granularity.

Looking forward for either @arif-ali or @TurboTurtle review.

champtar changed the title ~~[plugins] speedup journal collection~~ [plugins] speedup journal collection (v2) Dec 13, 2024

champtar mentioned this pull request Dec 13, 2024

[plugins] speedup big journal collection #3873

Closed

6 tasks

champtar marked this pull request as draft December 13, 2024 05:00

champtar force-pushed the journal-speed2 branch from cc1c0a8 to b4534fd Compare December 13, 2024 05:10

pmoravec reviewed Dec 18, 2024

View reviewed changes

sos/report/plugins/__init__.py Outdated Show resolved Hide resolved

champtar force-pushed the journal-speed2 branch from b4534fd to 63c2a52 Compare January 25, 2025 06:52

github-advanced-security bot found potential problems Jan 25, 2025

View reviewed changes

sos/utilities.py Fixed Show fixed Hide fixed

champtar force-pushed the journal-speed2 branch 6 times, most recently from b23de87 to 04f3361 Compare January 26, 2025 02:28

github-advanced-security bot found potential problems Jan 26, 2025

View reviewed changes

champtar force-pushed the journal-speed2 branch 2 times, most recently from 89fc059 to 2ff50e2 Compare January 26, 2025 03:26

champtar marked this pull request as ready for review January 26, 2025 03:31

champtar changed the title ~~[plugins] speedup journal collection (v2)~~ [utilities,plugins] speedup journal collection (v2) Jan 26, 2025

champtar force-pushed the journal-speed2 branch from 2ff50e2 to 5fb7009 Compare January 26, 2025 04:30

pmoravec reviewed Jan 29, 2025

View reviewed changes

sos/utilities.py Show resolved Hide resolved

pmoravec reviewed Jan 29, 2025

View reviewed changes

sos/utilities.py Outdated Show resolved Hide resolved

pmoravec reviewed Jan 29, 2025

View reviewed changes

sos/utilities.py Show resolved Hide resolved

pmoravec reviewed Jan 31, 2025

View reviewed changes

sos/utilities.py Show resolved Hide resolved

champtar added 5 commits January 31, 2025 18:55

[utilities] Rename AsyncReader to TailReader

3fe0db4

We are going to introduce HeadReader. Signed-off-by: Etienne Champetier <[email protected]>

[utilities] Add HeadReader

deee400

Will be used to keep the first sizelimit MB from a program stdout. Signed-off-by: Etienne Champetier <[email protected]>

[utilities,plugins] Wire up tac_logs and HeadReader

38e32ca

Using sizelimit with to_file now keep the start of the command output instead of being ignored. You can use tac with and without sizelimit. Signed-off-by: Etienne Champetier <[email protected]>

champtar force-pushed the journal-speed2 branch from 5fb7009 to 060f50f Compare January 31, 2025 23:56

pmoravec approved these changes Feb 2, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[utilities,plugins] speedup journal collection (v2) #3879

[utilities,plugins] speedup journal collection (v2) #3879

champtar commented Dec 13, 2024

packit-as-a-service bot commented Dec 13, 2024

pmoravec commented Dec 18, 2024

champtar commented Dec 18, 2024

pmoravec commented Dec 18, 2024

pmoravec commented Jan 19, 2025

pmoravec Jan 31, 2025

champtar commented Jan 26, 2025

pmoravec commented Jan 29, 2025

champtar commented Jan 30, 2025

pmoravec commented Jan 30, 2025

pmoravec commented Jan 31, 2025

pmoravec commented Feb 1, 2025

champtar commented Feb 1, 2025

pmoravec left a comment

[utilities,plugins] speedup journal collection (v2) #3879

Are you sure you want to change the base?

[utilities,plugins] speedup journal collection (v2) #3879

Conversation

champtar commented Dec 13, 2024

packit-as-a-service bot commented Dec 13, 2024

pmoravec commented Dec 18, 2024

champtar commented Dec 18, 2024

pmoravec commented Dec 18, 2024

pmoravec commented Jan 19, 2025

pmoravec Jan 31, 2025

Choose a reason for hiding this comment

champtar commented Jan 26, 2025

pmoravec commented Jan 29, 2025

champtar commented Jan 30, 2025

pmoravec commented Jan 30, 2025

pmoravec commented Jan 31, 2025

pmoravec commented Feb 1, 2025

champtar commented Feb 1, 2025

pmoravec left a comment

Choose a reason for hiding this comment