Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Showing status of service via systemctl is slow (>10s) if disk journal is used #2460

Open
XANi opened this Issue Jan 28, 2016 · 17 comments

Comments

6 participants
@XANi
Copy link

XANi commented Jan 28, 2016

With big (4GB, few months of logs) on-disk journal, systemctl status service becomes very slow

 (!) [13:37:30]:/var/log/journal☠ time  systemctl status nginx
* nginx.service - A high performance web server and a reverse proxy server
   Loaded: loaded (/lib/systemd/system/nginx.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2016-01-28 08:25:28 CET; 5h 12min ago
 Main PID: 3414 (nginx)
   CGroup: /system.slice/nginx.service
           |-3414 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
           |-3415 nginx: worker process
           |-3416 nginx: worker process
           |-3417 nginx: worker process
           `-3418 nginx: worker process

Jan 28 08:25:12 ghroth systemd[1]: Starting A high performance web server and a reverse proxy server...
Jan 28 08:25:28 ghroth systemd[1]: Started A high performance web server and a reverse proxy server.

real    0m12.505s
user    0m0.016s
sys 0m0.056s
 (!) [13:35:14]:/var/log/journal☠ du -h --max=1
4,2G    ./46feef66e59512fcd99c7ddc00000108
4,2G    .
 (!) [13:40:53]:/var/log/journal☠ strace systemctl status nginx 2>&1 |grep open |grep /var/log |wc -l
88

it is of course faster after it gets to cache... for that service, querying other one is still slow.

Dunno what would be right way to do it.. but opening ~80 log files to just display service status seems a bit excessive

@poettering

This comment has been minimized.

Copy link
Member

poettering commented Jan 28, 2016

is this on hdd or ssd?

But yeah, we scale badly if we have too many individual files to combine. It's O(n) with each file we get...

@poettering poettering added the journal label Jan 28, 2016

@XANi

This comment has been minimized.

Copy link
Author

XANi commented Jan 28, 2016

This one was on HDD, but now that I've looked into it it can be a bit (~0.5s, HDD swap, 300MB of logs on tmpfs) slow even with tmpfs if part that was loaded happened to be swapped out (I was testing on system with 2 weeks of uptime)

Shouldn't there be some kind of index on journal files ? Or at the very least pointer in service entry to last log file that have relevant log entries .

@davispuh

This comment has been minimized.

Copy link

davispuh commented Oct 1, 2016

I think some kind of journal indexing is required because it's unbearably slow.

Right now I've 5411 (43 GiB) journal files and

$ time -p journalctl -b --no-pager > /dev/null
real 13.61
user 13.37
sys 0.22

it takes 13 seconds to just check current boot log while it's already cached in RAM.

When it's not cached

# echo 3 > /proc/sys/vm/drop_caches
$ time -p journalctl -b --no-pager > /dev/null
real 69.29
user 13.51
sys 12.34

this is on 2x 3TB HDD with RAID1 btrfs.

@XANi

This comment has been minimized.

Copy link
Author

XANi commented Oct 1, 2016

It is laggy even when it is on tmpfs and machine runs long enough to swap it out.

Why journald doesn't just use SQLite for storage ? It would be faster and other apps could actually use logfiles for something useful and have good query language instead of relying on a bunch of options in journalctl

@XANi

This comment has been minimized.

Copy link
Author

XANi commented Jun 21, 2017

It is still slow as hell:

time systemctl status kdm|cat
* kdm.service - LSB: X display manager for KDE
   Loaded: loaded (/etc/init.d/kdm; generated; vendor preset: enabled)
   Active: active (exited) since Wed 2017-06-21 12:03:26 CEST; 1h 42min ago
     Docs: man:systemd-sysv-generator(8)
    Tasks: 0 (limit: 4915)
   CGroup: /system.slice/kdm.service

Jun 21 12:03:25 ghroth systemd[1]: Starting LSB: X display manager for KDE...
Jun 21 12:03:26 ghroth systemd[1]: Started LSB: X display manager for KDE.

real	0m2.873s
user	0m0.008s
sys	0m0.016s

and it opens over hundred (on system that was up 2 hours)

strace systemctl status kdm 2>&1 |grep open |wc -l
133
@vcaputo

This comment has been minimized.

Copy link
Member

vcaputo commented Jul 7, 2017

@XANi @davispuh is there any chance you could run your slow cases under valgrind --tool=callgrind and supply us with the the output? I've seen some pathological cases where journalctl is spending exorbitant (~50% of its execution) amounts of CPU time in the siphash24 code when the simple context cache in the mmap-cache is experiencing high miss rates, I'm curious if that's also something you guys are observing here.

@davispuh

This comment has been minimized.

Copy link

davispuh commented Jul 8, 2017

@vcaputo

This comment has been minimized.

Copy link
Member

vcaputo commented Jul 8, 2017

@davispuh Thank you for quickly providing the profiles. The callgrind.out.systemctl-status-sshd.gz profile shows mmap_cache_get() somewhat prominently with the hashmap maintenance being a significant part of that.

It's not a panacea, but #6307 may improve the runtime of systemctl status sshd for you. Would you be up for some testing? Some time systemctl status sshd --no-pager comparisons before and after would be great.

For anybody reading, the kcachegrind utility works quite well for visualizing callgrind.out files.

@davispuh

This comment has been minimized.

Copy link

davispuh commented Jul 9, 2017

Emm, I can't test this anymore since after I compiled and reinstalled systemd it reset my /etc/systemd/journald.conf settings and so systemd deleted all old journals and it's fast now again. Basically it's slow only when you've a lot of journal files in /var/log/journal/

@davispuh

This comment has been minimized.

Copy link

davispuh commented Oct 5, 2017

With just complied from fdb6343

When files aren't cached it's really unusably slow

$ time systemctl status sshd --no-pager
0.28user 34.82system 4:34.32elapsed 12%CPU (0avgtext+0avgdata 1355416maxresident)k
3242224inputs+0outputs (10002major+17658minor)pagefaults 0swaps

2nd time when it's cached it's quick

$ time systemctl status sshd --no-pager
0.09user 0.33system 0:00.43elapsed 99%CPU (0avgtext+0avgdata 1303540maxresident)k
0inputs+0outputs (0major+23705minor)pagefaults 0swaps

callgrind when it's not cached and when it is

callgrind.out.systemctl-status-sshd_nocache.gz
callgrind.out.systemctl-status-sshd_cached.gz

I've 7542 *.journal files in /var/log/journal/<ID> which is on BTRFS RAID1 partition (2x 3TB HDD)

Basically to improve performance need to do less disk reading. Like use some kind of indexing or something like that.

@amishmm

This comment has been minimized.

Copy link

amishmm commented Mar 31, 2018

I have 240 system log files and 860 user log files.

systemctl status OR journalctl -f take 2-4 minutes just to display logs. (HDD drive)

I have added this in: /usr/lib/systemd/journald.conf.d/90-custom.conf

[Journal]
SystemMaxUse=100G
SystemMaxFileSize=200M
SystemMaxFiles=1100
MaxFileSec=1week
MaxRetentionSec=3year

Systemd generates 2 to 3 system journal files everyday each of about 150994944 bytes size.

Why doesnt journalctl -f (or systemctl) check only latest / current journal?

How do I make it efficient and fast? I need to preserve logs for long duration.

In most cases most people only have to check recent logs only.

May be some feature to have automatic archival of logs in different directory (/var/log/journal/ID-DIRECTORY/archive) and current logs (say past 3-7 days) kept in /var/log/journal/ID-DIRECTORY?

This will speed up journalctl and systemctl status a lot. Anyone want to check archived logs can use --directory option of journalctl

@Gunni

This comment has been minimized.

Copy link

Gunni commented Apr 20, 2018

I have the same problem, i'm on a vmware vm on a hdd san

example: time systemctl status systemd-journald.service

real    0m50.484s
user    0m0.070s
sys     0m3.492s

journal size is: 101.1GB right now.

@amishmm

This comment has been minimized.

Copy link

amishmm commented Jun 5, 2018

journalctl has --file parameter. I am able to use it to search faster.

while:
journalctl -f took ages

journalctl --file /var/log/journal/*/system.journal -f takes just 1-2 seconds.

Similarly can we make systemctl status use ONLY system.journal by default? Because in most cases administrator check status only after systemctl (re)start or when something unexpected happens (which is also likely to be logged in system.journal unless it rotated just recently)

This will drastically speed things up.

If admin wants older status he can supply --lines=N in which case systemctl will scan through older journals too. (may be in reverse order) OR admin can use journalctl -n N -u service instead

PS: I have no idea how data is stored in journal.

@poettering do u want me to create RFE for this?

PPS: Now every time I run systemctl status it becomes as good as DoS attack!

@Gunni

This comment has been minimized.

Copy link

Gunni commented Jun 5, 2018

Yes this is a problem for servers storing their logs.

My biggest problem is the centralized log server, i receive logs from network equipment using rsyslog, and it uses omjournal to pipe them directly into journal. It works fine to begin with but then degrades quickly (note i'm doing this as a test server, we have another server where rsyslog writes to files).

Maybe journal files could be made to contain specific timespans, and only get loaded if requested, i use stuff like --since and --until a lot but since they are affected by this, it doesn't help, but if the file method were used, journalctl could find them in fractions of seconds, -f should just be instant really, find the last 10 entries, and only search backwards in time if nothing happened maybe with a cutoff.

@XANi

This comment has been minimized.

Copy link
Author

XANi commented Jun 6, 2018

@amishxda IMO status by default should just... not have to touch on-disk logs, ever. Storing few last lines of log in memory per service wouldn't be that memory hungry, wouldn't trash OS disk cache on status and it would return something more useful than "welp, logs were rotated, too bad" that it currently does when server runs for some time.

It should only fetch more log lines from journalctl if explictly requested by user

@Gunni I don't think using systemd for centralized log server is intended, or good idea in the first place. ELK stack is much more useful for it, jankiness aside Logstash allows to do a lot of nice stuff, for example we use it to split iptables logs into fields (srcip/dstip/port etc) before putting in ES. And ES just works better for search

@Gunni

This comment has been minimized.

Copy link

Gunni commented Jun 6, 2018

@XANi I just expected it to be a supported use case since systemd-journal-remote is a thing but if this is the expected performance, ofcourse. But if it is improved, maybe add a better index or a database backend to journal then i'd be able to use it.

About the tools you mentioned, setting up all that stuff sounds like much more work, especially since we like to be able to watch the logs live journalctl SRC=net -f (maybe with a grep), the second they arrive, my expirience with what you mentioned has been long delay from event to user. But i'll look into it.

@XANi

This comment has been minimized.

Copy link
Author

XANi commented Jun 7, 2018

@Gunni I wish journald would just use sqlite instead of its current half-assed binary db. I feel like currently it is just trying to reimplement that but badly. And there is a plenty of tools for querying sqlite already.

ELK stack is definitely more effort to put in but in exchange it has a ton of nice features to look at, we for example made logstash do geoIP lookup on any IP that's not private so each firewall log gets that info added.

Querying is also very nice as you can make a queries on fields directly instead of text strings

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.