Arch Linux

railmaniac

Member

Registered: 2010-04-24

Posts: 24

[SOLVED] systemd 208 journald process CPU spike on LXC container start

Hi,

The problem is that whenever I start an LXC container, systemd-journald process goes on 100% CPU utilization and only stops when I stop the container.

Setup details:

% cat /var/lib/lxc/projects/config
lxc.network.type = veth
lxc.arch = x86_64
lxc.utsname = projects
lxc.network.link = virbr3
lxc.network.flags = up
lxc.network.ipv4 = 192.168.200.11
lxc.rootfs = /mnt/lxc/projects
lxc.pts = 1000
lxc.autodev = 1
lxc.cgroup.memory.limit_in_bytes = 256M

The rootfs indicated is on a logical volume, /dev/mapper/virtual-projects.

Details of journal when the spike happened:

-- Logs begin at Sun 2013-08-04 07:19:25 IST. --
Oct 05 09:03:30 core systemd[1]: Unit lxc@projects.service entered failed state.
Oct 05 09:03:30 core kernel: virbr3: port 2(vethl7BeWT) entered disabled state
Oct 05 09:03:30 core kernel: device vethl7BeWT left promiscuous mode
Oct 05 09:03:30 core kernel: virbr3: port 2(vethl7BeWT) entered disabled state
Oct 05 09:03:31 core ntpd[813]: Deleting interface #13 vethl7BeWT, fe80::fcf2:f2ff:fea0:9473#123, interface stats: received=0, sent=0, dropped=0, active_time=11 secs
Oct 05 09:03:31 core ntpd[813]: peers refreshed
Oct 05 09:03:40 core dbus-daemon[533]: dbus[533]: [system] Activating via systemd: service name='org.freedesktop.ModemManager1' unit='dbus-org.freedesktop.ModemManager1.service'
Oct 05 09:03:40 core dbus[533]: [system] Activating via systemd: service name='org.freedesktop.ModemManager1' unit='dbus-org.freedesktop.ModemManager1.service'
Oct 05 09:03:40 core dbus[533]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.ModemManager1.service': Unit dbus-org.freedesktop.ModemManager1.service failed to load: No such file or directory.
Oct 05 09:03:40 core dbus-daemon[533]: dbus[533]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.ModemManager1.service': Unit dbus-org.freedesktop.ModemManager1.service failed to load: No such file or directory.
Oct 05 09:05:30 core systemd[1]: Starting Linux Container projects...
Oct 05 09:05:30 core systemd[1]: Started Linux Container projects.
Oct 05 09:05:30 core systemd-sysctl[4562]: Overwriting earlier assignment of kernel/sysrq in file '/etc/sysctl.d/zz-sysctl.conf'.
Oct 05 09:05:30 core kernel: device vethmHU7wo entered promiscuous mode
Oct 05 09:05:30 core kernel: IPv6: ADDRCONF(NETDEV_UP): vethmHU7wo: link is not ready
Oct 05 09:05:30 core NetworkManager[521]: <warn> /sys/devices/virtual/net/vethSIUSbq: couldn't determine device driver; ignoring...
Oct 05 09:05:30 core systemd-sysctl[4564]: Overwriting earlier assignment of kernel/sysrq in file '/etc/sysctl.d/zz-sysctl.conf'.
Oct 05 09:05:30 core kernel: virbr3: topology change detected, propagating
Oct 05 09:05:30 core kernel: virbr3: port 2(vethmHU7wo) entered forwarding state
Oct 05 09:05:30 core kernel: virbr3: port 2(vethmHU7wo) entered forwarding state
Oct 05 09:05:30 core kernel: virbr3: port 2(vethmHU7wo) entered disabled state
Oct 05 09:05:30 core NetworkManager[521]: <warn> /sys/devices/virtual/net/vethmHU7wo: couldn't determine device driver; ignoring...
Oct 05 09:05:30 core kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethmHU7wo: link becomes ready
Oct 05 09:05:30 core kernel: virbr3: topology change detected, propagating
Oct 05 09:05:30 core kernel: virbr3: port 2(vethmHU7wo) entered forwarding state
Oct 05 09:05:30 core kernel: virbr3: port 2(vethmHU7wo) entered forwarding state
Oct 05 09:05:30 core libvirtd[809]: nl_recv returned with error: No buffer space available
Oct 05 09:05:30 core upowerd[660]: (upowerd:660): UPower-Linux-WARNING **: treating add event as change event on /org/freedesktop/UPower/devices/line_power_AC0
Oct 05 09:05:30 core systemd-logind[516]: Watching system buttons on /dev/input/event3 (Power Button)
Oct 05 09:05:30 core upowerd[660]: (upowerd:660): UPower-Linux-WARNING **: treating add event as change event on /org/freedesktop/UPower/devices/battery_BAT0
Oct 05 09:05:30 core systemd-logind[516]: Watching system buttons on /dev/input/event5 (Video Bus)
Oct 05 09:05:30 core systemd-logind[516]: Watching system buttons on /dev/input/event2 (Sleep Button)
Oct 05 09:05:30 core systemd-logind[516]: Watching system buttons on /dev/input/event1 (Lid Switch)
Oct 05 09:05:30 core systemd-logind[516]: Watching system buttons on /dev/input/event4 (Video Bus)
Oct 05 09:05:30 core mtp-probe[4711]: checking bus 3, device 4: "/sys/devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.2"
Oct 05 09:05:30 core mtp-probe[4712]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.4"
Oct 05 09:05:30 core mtp-probe[4711]: bus: 3, device: 4 was not an MTP device
Oct 05 09:05:30 core mtp-probe[4712]: bus: 3, device: 5 was not an MTP device
Oct 05 09:05:30 core systemd-udevd[4561]: error opening ATTR{/sys/devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.4/3-1.4:1.0/host6/scsi_host/host6/link_power_management_policy} for writing: No such file or directory
Oct 05 09:05:32 core ntpd[813]: Listen normally on 14 vethmHU7wo fe80::fcf0:74ff:fe68:aade UDP 123
Oct 05 09:05:32 core ntpd[813]: peers refreshed
Oct 05 09:05:32 core ntpd[813]: new interface(s) found: waking up resolver
Oct 05 09:05:40 core dbus-daemon[533]: dbus[533]: [system] Activating via systemd: service name='org.freedesktop.ModemManager1' unit='dbus-org.freedesktop.ModemManager1.service'
Oct 05 09:05:40 core dbus[533]: [system] Activating via systemd: service name='org.freedesktop.ModemManager1' unit='dbus-org.freedesktop.ModemManager1.service'
Oct 05 09:05:40 core dbus[533]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.ModemManager1.service': Unit dbus-org.freedesktop.ModemManager1.service failed to load: No such file or directory.
Oct 05 09:05:40 core dbus-daemon[533]: dbus[533]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.ModemManager1.service': Unit dbus-org.freedesktop.ModemManager1.service failed to load: No such file or directory.
Oct 05 09:06:15 core kernel: EXT4-fs (dm-10): re-mounted. Opts: commit=600
Oct 05 09:06:15 core kernel: EXT4-fs (dm-12): re-mounted. Opts: acl,commit=600
Oct 05 09:06:15 core kernel: EXT4-fs (dm-18): re-mounted. Opts: commit=600
Oct 05 09:06:15 core kernel: EXT4-fs (sda1): re-mounted. Opts: commit=600
Oct 05 09:06:16 core kernel: EXT4-fs (sda4): re-mounted. Opts: acl,commit=600
Oct 05 09:06:21 core kernel: EXT4-fs (dm-10): re-mounted. Opts: commit=0
Oct 05 09:06:21 core kernel: EXT4-fs (dm-12): re-mounted. Opts: acl,commit=0
Oct 05 09:06:21 core kernel: EXT4-fs (dm-18): re-mounted. Opts: commit=0
Oct 05 09:06:21 core kernel: EXT4-fs (sda1): re-mounted. Opts: commit=0
Oct 05 09:06:28 core kernel: EXT4-fs (dm-10): re-mounted. Opts: commit=600
Oct 05 09:06:28 core kernel: EXT4-fs (dm-12): re-mounted. Opts: acl,commit=600
Oct 05 09:06:28 core kernel: EXT4-fs (dm-18): re-mounted. Opts: commit=600
Oct 05 09:06:28 core kernel: EXT4-fs (sda1): re-mounted. Opts: commit=600
Oct 05 09:06:28 core kernel: EXT4-fs (sda4): re-mounted. Opts: acl,commit=600
Oct 05 09:06:31 core kernel: EXT4-fs (dm-10): re-mounted. Opts: commit=0
Oct 05 09:06:31 core kernel: EXT4-fs (dm-12): re-mounted. Opts: acl,commit=0
Oct 05 09:06:31 core kernel: EXT4-fs (dm-18): re-mounted. Opts: commit=0
Oct 05 09:06:31 core kernel: EXT4-fs (sda1): re-mounted. Opts: commit=0
Oct 05 09:06:38 core systemd[1]: Stopping Linux Container projects...
Oct 05 09:06:38 core systemd[1]: lxc@projects.service: main process exited, code=exited, status=137/n/a
Oct 05 09:06:38 core systemd[1]: Stopped Linux Container projects.
Oct 05 09:06:38 core systemd[1]: Unit lxc@projects.service entered failed state.
Oct 05 09:06:38 core kernel: virbr3: port 2(vethmHU7wo) entered disabled state
Oct 05 09:06:38 core kernel: device vethmHU7wo left promiscuous mode
Oct 05 09:06:38 core kernel: virbr3: port 2(vethmHU7wo) entered disabled state
Oct 05 09:06:39 core ntpd[813]: Deleting interface #14 vethmHU7wo, fe80::fcf0:74ff:fe68:aade#123, interface stats: received=0, sent=0, dropped=0, active_time=67 secs
Oct 05 09:06:39 core ntpd[813]: peers refreshed

Nothing really leaps out to me.

This only happens on Systemd-208. Rolling back to systemd-207 resolved the issue for now, but I can't help but wonder if I won't have this problem again on systemd-209 or whatever. Is there any additional configuration that I need to do in order to get LXC working properly with systemd 208+?

Also, I don't know if this is relevant, but I got some filesystem permissions warnings on upgrading (and later downgrading) systemd.

Last edited by railmaniac (2013-10-12 14:03:47)

---

Thanks,
railmaniac

railmaniac

Member

Registered: 2010-04-24

Posts: 24

Re: [SOLVED] systemd 208 journald process CPU spike on LXC container start

I've had a breakthrough on this. Apparently it's the instance of systemd-journald inside the container that is spiking. I was able to upgrade to systemd 208 on the real root, and there was no issue starting the container, which was still on systemd 207. But when I upgraded systemd inside the container I was able to replicate the issue successfully.

So here are steps to replicate, if anyone can do it I'll be assured that this is not just an issue with my configuration.

1. Install LXC

pacman -S lxc

2. Create a rootfs for arch. Done soon, this should set systemd to version 208.

mkdir -p rootfs/var/lib/pacman/{local,sync}
pacman -S base -r rootfs

3. Create an LXC container

lxc-create -n test_container

4. Set the rootfs of the container to where arch was installed

echo lxc.rootfs '=' /absolute/path/to/rootfs >> /var/lib/lxc/test_container/config

5. Start the container

lxc-start -n test_container

Observation: systemd-journald process on the container occupies 100% CPU.

I have downgraded systemd inside the container to 207, and I will put a HoldPkg for systemd and systemd-sysvcompat on the guest. Since I don't really care for the version of systemd inside the container and I'm not held on upgrading on my main root, this is effectively resolved from my side. But I don't know why this was happening.

---

Thanks,
railmaniac

railmaniac

Member

Registered: 2010-04-24

Posts: 24

Re: [SOLVED] systemd 208 journald process CPU spike on LXC container start

Some journal entries from the guest

There's a bunch of these:

ct 12 18:52:24 projects systemd-udevd[30]: Failed to apply ACL on /dev/dri/card0: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[38]: Failed to apply ACL on /dev/snd/hwC0D3: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[42]: Failed to apply ACL on /dev/snd/pcmC0D0c: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[37]: Failed to apply ACL on /dev/snd/hwC0D0: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[44]: Failed to apply ACL on /dev/snd/pcmC0D3p: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[43]: Failed to apply ACL on /dev/snd/pcmC0D0p: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[31]: Failed to apply ACL on /dev/snd/controlC0: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[35]: inotify_add_watch(7, /dev/sda, 10) failed: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[36]: Failed to apply ACL on /dev/sr0: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[34]: Failed to apply ACL on /dev/sg1: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[28]: Error, opening device '/dev/input/event12': No such file or directory
Oct 12 18:52:24 projects systemd-udevd[32]: Failed to apply ACL on /dev/video0: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[25]: inotify_add_watch(7, /dev/sdb, 10) failed: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[33]: Failed to apply ACL on /dev/kvm: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[29]: inotify_add_watch(7, /dev/sda1, 10) failed: No such file or directory
Oct 12 18:52:24 projects systemd[1]: Listening on D-Bus System Message Bus Socket.
Oct 12 18:52:24 projects systemd-udevd[30]: inotify_add_watch(7, /dev/sda2, 10) failed: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[27]: Failed to apply ACL on /dev/snd/timer: No such file or directory
Oct 12 18:52:24 projects systemd[1]: Starting Sockets.
Oct 12 18:52:24 projects systemd-udevd[35]: inotify_add_watch(7, /dev/sda4, 10) failed: No such file or directory
Oct 12 18:52:24 projects systemd-udevd[31]: inotify_add_watch(7, /dev/sda3, 10) failed: No such file or directory

And there's a bunch of these, which seems relevant since the logind part was changed in 208:

Oct 12 18:52:24 projects systemd-logind[59]: New seat seat0.
Oct 12 18:52:24 projects systemd[1]: Startup finished in 487ms.
Oct 12 18:52:24 projects systemd-logind[59]: Failed to open event3: No such file or directory
Oct 12 18:52:24 projects systemd-logind[59]: Failed to open event5: No such file or directory
Oct 12 18:52:24 projects systemd-logind[59]: Failed to open event4: No such file or directory
Oct 12 18:52:24 projects systemd-logind[59]: Failed to open event1: No such file or directory
Oct 12 18:52:24 projects systemd-logind[59]: Failed to open event2: No such file or directory
Oct 12 18:52:26 projects systemd-journal[64]: Permanent journal is using 87.6M (max 30.0M, leaving 1.1G of free 4.4G, current limit 30.0M).
Oct 12 18:52:26 projects systemd-journal[64]: Journal started
Oct 12 18:52:26 projects systemd[1]: systemd-journald.service: main process exited, code=exited, status=1/FAILURE
Oct 12 18:52:26 projects systemd[1]: Unit systemd-journald.service entered failed state.
Oct 12 18:52:26 projects systemd[1]: Starting Trigger Flushing of Journal to Persistent Storage...
Oct 12 18:52:26 projects systemd[1]: Started Trigger Flushing of Journal to Persistent Storage.

Hmm, just noticed it says systemd-journald exited with FAILURE. This is probably pretty informative to someone.

---

Thanks,
railmaniac

railmaniac

Member

Registered: 2010-04-24

Posts: 24

Re: [SOLVED] systemd 208 journald process CPU spike on LXC container start

Marking as solved since this is not an issue for me anymore.

---

Thanks,
railmaniac