Arch Linux

bicyclingrevolution

Member

Registered: 2010-10-18

Posts: 71

(Solved) systemd-journald extremely high CPU usage

I started noticing this problem a few days ago, but I thought it was because I was running too much with too little RAM. But when running nothing more than a KDE desktop, my CPU usage bounces between 50% and 100%, making things laggy. It looks like systemd-journald is to blame, as it is using 50% of the CPU. This is an AMD Phenom II dual core, so this definitely shouldn't be happening. I noticed journal logs were more than 2 GB, so I deleted everything within /var/log/journal/. Rebooted, no change, so I disabled journal storage, but that did not solve the problem.
Nothing in the logs looks like a problem to me:

$ sudo journalctl 
-- Logs begin at Tue 2013-03-12 17:31:37 PDT, end at Tue 2013-03-12 18:15:56 PDT. --
Mar 12 17:31:37 silverstone systemd-journal[149]: Allowing runtime journal files to grow to 298.6M.
Mar 12 17:31:37 silverstone kernel: Initializing cgroup subsys cpuset
Mar 12 17:31:37 silverstone kernel: Initializing cgroup subsys cpu
Mar 12 17:31:37 silverstone kernel: Linux version 3.7.10-1-ARCH (tobias@T-POWA-LX) (gcc version 4.7.2 (G
Mar 12 17:31:37 silverstone kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-linux root=UUID=31669ea0-76db
Mar 12 17:31:37 silverstone kernel: e820: BIOS-provided physical RAM map:
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009efff] usable
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x000000000009f000-0x000000000009ffff] reserved
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x00000000000e2000-0x00000000000fffff] reserved
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000cff8ffff] usable
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x00000000cff90000-0x00000000cff9dfff] ACPI data
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x00000000cff9e000-0x00000000cffdffff] ACPI NVS
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x00000000cffe0000-0x00000000cfffffff] reserved
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x00000000ffe00000-0x00000000ffffffff] reserved
Mar 12 17:31:37 silverstone kernel: BIOS-e820: [mem 0x0000000100000000-0x00000001afffffff] usable
Mar 12 17:31:37 silverstone kernel: NX (Execute Disable) protection: active
Mar 12 17:31:37 silverstone kernel: SMBIOS 2.5 present.
Mar 12 17:31:37 silverstone kernel: DMI: MSI MS-7642/890GXM-G65 (MS-7642)  , BIOS V1.2 03/31/2010
Mar 12 17:31:37 silverstone kernel: e820: update [mem 0x00000000-0x0000ffff] usable ==> reserved
Mar 12 17:31:37 silverstone kernel: e820: remove [mem 0x000a0000-0x000fffff] usable
Mar 12 17:31:37 silverstone kernel: No AGP bridge found
Mar 12 17:31:37 silverstone kernel: e820: last_pfn = 0x1b0000 max_arch_pfn = 0x400000000
Mar 12 17:31:37 silverstone kernel: MTRR default type: uncachable
Mar 12 17:31:37 silverstone kernel: MTRR fixed ranges enabled:
Mar 12 17:31:37 silverstone kernel:   00000-9FFFF write-back
Mar 12 17:31:37 silverstone kernel:   A0000-EFFFF uncachable
Mar 12 17:31:37 silverstone kernel:   F0000-FFFFF write-protect
Mar 12 17:31:37 silverstone kernel: MTRR variable ranges enabled:
Mar 12 17:31:37 silverstone kernel:   0 base 000000000000 mask FFFF80000000 write-back
Mar 12 17:31:37 silverstone kernel:   1 base 000080000000 mask FFFFC0000000 write-back
Mar 12 17:31:37 silverstone kernel:   2 base 0000C0000000 mask FFFFF0000000 write-back
Mar 12 17:31:37 silverstone kernel:   3 disabled
Mar 12 17:31:37 silverstone kernel:   4 disabled
Mar 12 17:31:37 silverstone kernel:   5 disabled
Mar 12 17:31:37 silverstone kernel:   6 disabled                                                        
Mar 12 17:31:37 silverstone kernel:   7 disabled                                                        
Mar 12 17:31:37 silverstone kernel: TOM2: 00000001b0000000 aka 6912M                                    
Mar 12 17:31:37 silverstone kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106    
Mar 12 17:31:37 silverstone kernel: e820: update [mem 0xd0000000-0xffffffff] usable ==> reserved        
Mar 12 17:31:37 silverstone kernel: e820: last_pfn = 0xcff90 max_arch_pfn = 0x400000000
Mar 12 17:31:37 silverstone kernel: found SMP MP-table at [mem 0x000ff780-0x000ff78f] mapped at [ffff880
Mar 12 17:31:37 silverstone kernel: initial memory mapped: [mem 0x00000000-0x1fffffff]
Mar 12 17:31:37 silverstone kernel: Base memory trampoline at [ffff880000099000] 99000 size 24576

$ systemctl status systemd-journald
systemd-journald.service - Journal Service
          Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static)
          Active: active (running) since Tue 2013-03-12 18:10:41 PDT; 8min ago
            Docs: man:systemd-journald.service(8)
                  man:journald.conf(5)
        Main PID: 142 (systemd-journal)
          Status: "Processing requests..."
          CGroup: name=systemd:/system/systemd-journald.service
                  `-142 /usr/lib/systemd/systemd-journald

However, it looks like the log files keep getting corrupted:

$ sudo journalctl --verify
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@5e6edd359123491f9998a310206ccbf9-000000000007f543-0004d7c4445effa4.journal
Invalid object contents at 124687944ââââââââââââââââââââââââââââââââââââââââââ  49%
File corruption detected at /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-00000000000a8cb7-0004d7c3d52e9748.journal:124687944 (of 134074368, 92%).
FAIL: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-00000000000a8cb7-0004d7c3d52e9748.journal (Bad message)
Invalid object contents at 75715936âââââââââââââââââââââââââââââââââââââââââââ  49%
File corruption detected at /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system.journal:75715936 (of 76156928, 99%).
FAIL: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system.journal (Bad message)
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-00000000000290d6-0004d7c3a0033472.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@5e6edd359123491f9998a310206ccbf9-0000000000000001-0004d7c413227650.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/user-1000@0004d7c4153f62ea-dfaecd9845f367df.journal~
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-00000000000fcfc0-0004d7c3fd8ee9c5.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@0004d7c41325f6b2-0410ac8d7898ab18.journal~
Invalid object contents at 124701856ââââââââââââââââââââââââââââââââââââââââââ  49%
File corruption detected at /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-0000000000000001-0004d7c3876dda65.journal:124701856 (of 134049792, 93%).
FAIL: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-0000000000000001-0004d7c3876dda65.journal (Bad message)
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@5e6edd359123491f9998a310206ccbf9-00000000000a9da8-0004d7c45187e39e.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-00000000000d26b1-0004d7c3ea1b73f7.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@5e6edd359123491f9998a310206ccbf9-000000000002a43f-0004d7c425785944.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-00000000000539fb-0004d7c3b2d1f935.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@5e6edd359123491f9998a310206ccbf9-0000000000054d23-0004d7c4354da4ef.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/user-1000@2c1af599e637441985385fe37ded2a2c-0000000000001706-0004d7c38cd3de88.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/user-1000@5e6edd359123491f9998a310206ccbf9-00000000000019b4-0004d7c4153f8628.journal
PASS: /var/log/journal/9ddaa50d8841758bb1bea9b700000f33/system@2c1af599e637441985385fe37ded2a2c-000000000007e345-0004d7c3c3ed8197.journal

I am using a two or three year old SSD, so maybe it has gotten some bad sectors? But that doesn't explain why journald still bricks things when it isn't logging anything. The install is 10 months old, and I switched from init to systemd around October. Is there anything I can do, short of reinstalling?

Thanks,
Nicholas

Last edited by bicyclingrevolution (2013-03-14 05:57:13)

ilkyest

Member

From: Brazil

Registered: 2010-02-13

Posts: 269

Re: (Solved) systemd-journald extremely high CPU usage

try enabling madvise options

Poor copy performance to USB pendrive

If you experienced slow copy speed to pendrive (mainly in KDE), then merge this three line to the end of your /etc/rc.local:

echo madvise > /sys/kernel/mm/transparent_hugepage/enabled
echo madvise > /sys/kernel/mm/transparent_hugepage/defrag
echo 0 > /sys/kernel/mm/transparent_hugepage/khugepaged/defrag

And paste these at the end of your /etc/sysctl.conf

kernel.shmmax=134217728
vm.dirty_background_bytes = 4194304
vm.dirty_bytes = 4194304

Sometimes ago, I was presencing a very laggy acces, but I use "mechanic HDDs". And make it better with this. Until new kernel, this were succesfull

bicyclingrevolution

Member

Registered: 2010-10-18

Posts: 71

Re: (Solved) systemd-journald extremely high CPU usage

Thanks for the tip ilkyest, but it didn't make any difference to the systemd-journald problem.

However, I looked at journalctl again and found it cluttered with CUPS failures:

-- Logs begin at Tue 2013-03-12 19:17:00 PDT, end at Wed 2013-03-13 22:31:31 PDT. --
Mar 12 19:17:00 silverstone spideroak_inotify[796]: Program started
Mar 12 19:21:30 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:30 silverstone systemd-journal[143]: Suppressed 7199 messages from /system
Mar 12 19:21:27 silverstone systemd[1]: Starting CUPS Printing Service...
Mar 12 19:21:30 silverstone systemd-journal[143]: Suppressed 5471 messages from /system
Mar 12 19:21:27 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:30 silverstone systemd-journal[143]: Suppressed 5699 messages from /system
Mar 12 19:21:27 silverstone systemd[1]: Failed to start CUPS Printing Service.
Mar 12 19:21:27 silverstone systemd[1]: Starting CUPS Printing Service...
Mar 12 19:21:27 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:27 silverstone systemd[1]: Failed to start CUPS Printing Service.
Mar 12 19:21:27 silverstone systemd[1]: Starting CUPS Printing Service...
Mar 12 19:21:27 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:27 silverstone systemd[1]: Failed to start CUPS Printing Service.
Mar 12 19:21:27 silverstone systemd[1]: Starting CUPS Printing Service...
Mar 12 19:21:27 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:30 silverstone systemd-coredump[1592]: Process 1590 (cupsd) dumped core.
Mar 12 19:21:28 silverstone colord[354]: Profile added: Deskjet_3840-Gray..
Mar 12 19:21:28 silverstone colord[354]: Profile added: Deskjet_3840-RGB..
Mar 12 19:21:28 silverstone colord[354]: Device added: cups-Deskjet_3840
Mar 12 19:21:28 silverstone colord[354]: Profile added: Deskjet_F4100-Gray..
Mar 12 19:21:28 silverstone colord[354]: Profile added: Deskjet_F4100-RGB..
Mar 12 19:21:28 silverstone colord[354]: Device added: cups-Deskjet_F4100
Mar 12 19:21:28 silverstone dbus[337]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Mar 12 19:21:28 silverstone dbus[337]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service failed to load: No such file or directory. See system logs
Mar 12 19:21:28 silverstone colord[354]: Profile removed: Deskjet_3840-Gray..
Mar 12 19:21:28 silverstone colord[354]: Profile removed: Deskjet_3840-RGB..
Mar 12 19:21:28 silverstone colord[354]: device removed: cups-Deskjet_3840
Mar 12 19:21:31 silverstone colord[354]: Profile removed: Deskjet_F4100-Gray..
Mar 12 19:21:31 silverstone colord[354]: Profile removed: Deskjet_F4100-RGB..
Mar 12 19:21:31 silverstone colord[354]: device removed: cups-Deskjet_F4100
Mar 12 19:21:31 silverstone dbus-daemon[337]: dbus[337]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Mar 12 19:21:31 silverstone dbus-daemon[337]: dbus[337]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service failed to load: No such file or director
Mar 12 19:21:31 silverstone systemd-journal[143]: Missed 6365 kernel messages
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone cupsd[1590]: Unknown directive DefaultAuthType on line 9.
Mar 12 19:21:31 silverstone cupsd[1590]: cupsd: client.c:757: avahi_client_get_host_name: Assertion `client' failed.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone cupsd[1594]: Unknown directive DefaultAuthType on line 9.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.
Mar 12 19:21:31 silverstone systemd[1]: cups.service start request repeated too quickly, refusing to start.

Disabling cups solved the CPU usage issue.
It looks like the root of the problem is Avahi failing to start, but I have no idea why it isn't working.

$ systemctl status dbus-org.freedesktop.Avahi.service
dbus-org.freedesktop.Avahi.service
          Loaded: error (Reason: No such file or directory)
          Active: inactive (dead)

bicyclingrevolution

Member

Registered: 2010-10-18

Posts: 71

Re: (Solved) systemd-journald extremely high CPU usage

OK, I found out what was wrong. The Avahi service cups needed is actually called avahi-daemon.service, and it was not enabled. I've enabled that and cups.service, and everything is working properly again. The problem must have started when I was tweaking my printer's configuration and I enabled printer sharing--avahi is needed for that, but since it wasn't properly enabled in systemd, cups was freaking out and bogging down journald with all the errors. The only thing I don't understand is why the journals didn't show this problem until today.