Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.user > #224245 > unrolled thread

high cpu load systemd-journal, nobody logs

Back to article view | Back to linux.debian.user

Contents

  high cpu load systemd-journal, nobody logs Nico Becker <nico.becker@gmx.de> - 2020-07-01 10:20 +0200
    Re: high cpu load systemd-journal, nobody logs Reco <recoverym4n@enotuniq.net> - 2020-07-01 11:10 +0200

#224245 — high cpu load systemd-journal, nobody logs

hello,
i use debian 9 stretch (arm) for an small embedded project.
i install the systemd-journal-remote to read the log messages from the 
browser.
all the time i get an very high cpu load from the systemd-journal.
i think it is only if browse the syslog messages on 
http://ip_address_empedded_device:19531
PID  USER      PR  NI   VIRT    RES    SHR  S %CPU   %MEM  TIME+   
COMMAND
2289 systemd+  20   0   35996   4684   4032 S 100,7  0,5   9:03.25 
systemd-journal

i check the log messages, but nothing in the system logs anything.

i try strace to get some more debug information.
strace -ff -p (pid from systemd-journal)
and get the following output (only if the cpu load is heavy)
the pid from this log != the pid in top, its an fork. the poll event is 
endless.....
[log start]
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1) = 1 ([{fd=3, 
revents=POLLIN}]) <39.851333>
accept4(3, {sa_family=AF_INET6, sin6_port=htons(63652), 
inet_pton(AF_INET6, "::ffff:192.168.2.247", &sin6_addr), 
sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28], 
SOCK_CLOEXEC|SOCK_NONBLOCK) = 14 <0.002636>
clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=3642, tv_nsec=591554420}) 
= 0 <0.001027>
fcntl64(14, F_GETFL)                    = 0x802 (flags 
O_RDWR|O_NONBLOCK) <0.004664>
mmap2(NULL, 8388608, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb3400000 <0.001442>
mprotect(0xb3400000, 4096, PROT_NONE)   = 0 <0.001974>
clone(child_stack=0xb3bfeea8, 
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, 
parent_tidptr=0xb3bff3d8, tls=0xb3bff830, child_tidptr=0xb3bff3d8) = 
1931 <0.008147>
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1) = 1 ([{fd=3, 
revents=POLLIN}]) <0.008094>
accept4(3, {sa_family=AF_INET6, sin6_port=htons(63653), 
inet_pton(AF_INET6, "::ffff:192.168.2.247", &sin6_addr), 
sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28], 
SOCK_CLOEXEC|SOCK_NONBLOCK) = 17 <0.006013>
clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=3642, tv_nsec=661554420}) 
= 0 <0.002511>
fcntl64(17, F_GETFL)                    = 0x802 (flags 
O_RDWR|O_NONBLOCK) <0.001565>
mmap2(NULL, 8388608, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb2400000 <0.032403>
mprotect(0xb2400000, 4096, PROT_NONE)   = 0 <0.002686>
clone(child_stack=0xb2bfeea8, 
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, 
parent_tidptr=0xb2bff3d8, tls=0xb2bff830, child_tidptr=0xb2bff3d8) = 
1932 <0.214741>
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1) = 1 ([{fd=5, 
revents=POLLIN}]) <1.919831>
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1) = 1 ([{fd=5, 
revents=POLLIN}]) <0.000040>
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1) = 1 ([{fd=5, 
revents=POLLIN}]) <0.000036>
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1) = 1 ([{fd=5, 
revents=POLLIN}]) <0.000036>
... and so on
[log end]

Can somebody give me some hints?
i have no idea why the fork poll endless, and produce high cpu load.
i cant upgrade/update the system to an newer debian.



thanks a lot

[toc] | [next] | [standalone]

#224246

	Hi.

On Wed, Jul 01, 2020 at 09:48:00AM +0200, Nico Becker wrote:
> Can somebody give me some hints?

Sure. First, the poll(2) by itself is interesting, but useless if you
don't know what file descriptors 3 and 5 are referring to. So,

lsof -Pnp (pid from systemd-journal)

Or at least:

ls -al /proc/(pid from systemd-journal)/fd/3 /proc/(pid from systemd-journal)/fd/5


> i have no idea why the fork poll endless,

Second, the fork by itself, combined with accept(2) is the usual way to
process incoming connections (TCP connections in this case).
It's the amount of such connections that gives you the trouble.


> and produce high cpu load.

Third, and here's the most interesting part.
Your strace blurb shows multiple incoming connections from 192.168.2.247
(different source ports for each accept(2)). If the memory serves,
systemd-journal-remote should use HTTP for transferring the journal
records. While it's a pretty dumb design decision in general, it's
possible to use it to an advantage in a case like this, meaning:

tcpdump -pni any -c1024 -s0 -w /tmp/journal.pcap tcp port 19531

View the resulting file with Wireshark (or whatever equivalent), it
should contain the hints about the behaviour you're seeing.


The way I see it, systemd-journal-remote uses short-living HTTP to
"transfer" journal records to another system. "Transfer", because
contrary to the logic they've implemented "pull" mechanism for this, not
a "push" one.
While it gives you the ability to view journald records
(systemd-journald is a server, a browser is a client), it also mean that
your browser is forced to send numerous HTTP requests to the
systemd-journal-remote, effectively DOS'ing it.


> i cant upgrade/update the system to an newer debian.

Hardly relevant here, see above. Personally I'd say "screw it", and
would use conventional rsyslogd remote logging, but since it's a
embedded system - it may be impossible for you to follow this advice.

Reco

[toc] | [prev] | [standalone]

Back to top | Article view | linux.debian.user

csiph-web