Bug 61191

Confirmed, Arch Linux x86-64, systemd 197-4. I wasn't able to get an strace but in my case it wasn't a sustained problem. My fan kicked up I wondered what was causing it, pulled up htop and the journal was at 99% CPU on Core 0. Stayed like that for maybe 20seconds, then dropped back to normal. 

All I was doing was web browsing with Chromium and Rekonq. 

I find it odd that it hit 100% then eventually went back to normal, is there anything the journal does that should peg the CPU that hard? Or does systemd monitor the journal for hangs and restart it? (Did it hang, hence 100% cpu, systemd detected it, killed the journal and automatically restarted it?)

Since i know about what time the process hit 100%, would any of the journals logs be applicable as additional debug info? Or can you even sort the journals logs by time, at all?

Hmm, in that strace it appears that fd 8 seems to be causing EPIPE continiusly. By any chance, could you figure out what fd that is?

I.e. what does /proc/$PID/fd/8 and /proc/$PID/fdinfo/8 point to/contain?

There were a couple of reboots since then, so things changed.
I cannot see any more EPIPE error messages. As for the rest, the issue is still reproducible.
Currently strace shows the following:

clock_gettime(CLOCK_REALTIME, {1362639311, 615760612}) = 0
clock_gettime(CLOCK_REALTIME, {1362639311, 615791280}) = 0
writev(6, [{"<46>", 4}, {"systemd-journald", 16}, {"[21669]: ", 9}, {"Sleeping for 17492137 ms", 24}, {"\n", 1}], 5) = 54
epoll_wait(7, {?} 0xbfcf939c, 1, 17492137) = 1
read(8, "46,5081212822,316432051764,-;sys"..., 8192) = 79
clock_gettime(CLOCK_REALTIME, {1362639311, 615929585}) = 0
clock_gettime(CLOCK_REALTIME, {1362639311, 615959991}) = 0
writev(6, [{"<46>", 4}, {"systemd-journald", 16}, {"[21669]: ", 9}, {"Sleeping for 17492137 ms", 24}, {"\n", 1}], 5) = 54
epoll_wait(7, {?} 0xbfcf939c, 1, 17492137) = 1
read(8, "46,5081212823,316432051770,-;sys"..., 8192) = 79
clock_gettime(CLOCK_REALTIME, {1362639311, 616098321}) = 0
clock_gettime(CLOCK_REALTIME, {1362639311, 616128761}) = 0
writev(6, [{"<46>", 4}, {"systemd-journald", 16}, {"[21669]: ", 9}, {"Sleeping for 17492137 ms", 24}, {"\n", 1}], 5) = 54
epoll_wait(7, {?} 0xbfcf939c, 1, 17492137) = 1
read(8, "46,5081212824,316432051776,-;sys"..., 8192) = 79
clock_gettime(CLOCK_REALTIME, {1362639311, 616266463}) = 0
clock_gettime(CLOCK_REALTIME, {1362639311, 616296821}) = 0
writev(6, [{"<46>", 4}, {"systemd-journald", 16}, {"[21669]: ", 9}, {"Sleeping for 17492137 ms", 24}, {"\n", 1}], 5) = 54
epoll_wait(7, {?} 0xbfcf939c, 1, 17492137) = 1
read(8, "46,5081212825,316432051782,-;sys"..., 8192) = 79
clock_gettime(CLOCK_REALTIME, {1362639311, 616434289}) = 0
clock_gettime(CLOCK_REALTIME, {1362639311, 616464762}) = 0
writev(6, [{"<46>", 4}, {"systemd-journald", 16}, {"[21669]: ", 9}, {"Sleeping for 17492137 ms", 24}, {"\n", 1}], 5) = 54
epoll_wait(7, {?} 0xbfcf939c, 1, 17492137) = 1
read(8, "46,5081212826,316432051788,-;sys"..., 8192) = 79

Descriptors 6, 7 and 8 are as follows:

# ls -l /proc/21669/fd/6
l-wx------ 1 root root 64 Mar  7 00:29 /proc/21669/fd/6 -> /dev/kmsg
# ls -l /proc/21669/fd/7
lrwx------ 1 root root 64 Mar  7 00:29 /proc/21669/fd/7 -> anon_inode:[eventpoll]
# ls -l /proc/21669/fd/8
lrwx------ 1 root root 64 Mar  7 00:29 /proc/21669/fd/8 -> /dev/kmsg
#

BTW, when I set Storage=none the issue is not reproducible so I think this might be something with writing the logs.
So at the moment I can control and trigger this behaviour - set Storage back to the default value and restart journald.
If you need strace just after the journald restart I can try to get it.

Hmm, this seems to be a different loop, as this doesn't genreate EPIPE anymore.

This kinda appears to be a feedback loop: journald writes something to kmsg, and then reads it back, which it then writes a second time, and so on. Normally we should protect ourselves against that, but apparently that's not effective.

Do you have any special journal configuration set in journald.conf or on the kernel cmdline?

At the time when I discovered this issue, I had nothing custom set in the config.
Now it has:
SystemMaxUse=100M
MaxRetentionSec=1week

Same issue here (arch linux x86_64). This only happens if I set MaxRetentionSec in journald.conf. (archlinux package installs /var/log/journal by default so logs are not kept in ram)

See #45 post at https://bbs.archlinux.org/viewtopic.php?pid=1200373 , it can describe the issue better than I can.

I feel I was mistaken when I wrote that I discovered this issue with vanilla config. Anyway, I commented out the MaxRetentionSec for now and can confirm that the problem vanished.

This should be a fixed issue:
http://cgit.freedesktop.org/systemd/systemd/commit/?id=7964dfca1b6c4b37d069b3713f9f1b11219c3474