Bug 87424

Summary: Time-out problems during boot with systemd
Product: dbus Reporter: Paul Menzel <paulepanter>
Component: coreAssignee: D-Bus Maintainers <dbus>
Status: RESOLVED NOTOURBUG QA Contact: D-Bus Maintainers <dbus>
Severity: critical    
Priority: medium CC: paulepanter
Version: 1.8   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: Output of `sudo journalctl -l -b -3`

Description Paul Menzel 2014-12-17 21:40:43 UTC 
Using Debian Sid/unstable with D-Bus 1.8.12 and systemd 215-8, quite often several services do not start up during boot. I have no idea what actually triggers this.

When the service `systemd-logind.service` is unable to start up, it mostly results in a system where the grapical login manager GDM does not start. Often I am able to log in on tty1, but in rare cases `systemctl`, `poweroff`, `reboot` and `halt` do not work anymore, meaning I am unable to cleanly shut down the system and have to reset it.

I already reported this as bug #86431, but this turned into fixing a different problem or the fix was incomplete as I am still able to reproduce this with D-Bus 1.8.12.

The other question is, if it is actually a D-Bus or systemd problem. Or something entirely different.

Passing `systemd.debug-shell` mostly helps to get to GDM, suggesting this is some timing problem. But it also happens with it. Running `htop` the system is actually idle while logind times out. `systemctl status systemd-logind.service` also just contained the information that it timed out.

Logging in on tty1, the system stopped trying to (re)start logind over and over and it seemed to remain in the shutdown state.

Please tell me, what I should execute in the debug shell to debug it. Can I restart D-Bus for example.

I only tried the following:

        # dbus-monitor --system
        signal sender=org.freedesktop.DBus -> dest=:1.25 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
           string ":1.25"
        signal sender=org.freedesktop.DBus -> dest=(null destination) serial=30 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
           string ":1.26"
           string ""
           string ":1.26"
        signal sender=org.freedesktop.DBus -> dest=(null destination) serial=31 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
           string ":1.26"
           string ":1.26"
           string ""
        signal sender=org.freedesktop.DBus -> dest=(null destination) serial=32 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
           string ":1.27"
           string ""
           string ":1.27"
        signal sender=org.freedesktop.DBus -> dest=(null destination) serial=33 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
           string ":1.27"
           string ":1.27"
           string ""

while running the command below.

        $ strace -o 20141417--systemctl.strace systemctl status NetworkManager.service
        execve("/bin/systemctl", ["systemctl", "status", "NetworkManager.service"], [/* 17 vars */]) = 0
        brk(0)                                  = 0xb8388000
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb768b000
        access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
        open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
        fstat64(3, {st_mode=S_IFREG|0644, st_size=247187, ...}) = 0
        mmap2(NULL, 247187, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb764e000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/i686/cmov/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0p]\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0755, st_size=130488, ...}) = 0
        mmap2(NULL, 111276, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7632000
        mmap2(0xb764a000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0xb764a000
        mmap2(0xb764c000, 4780, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb764c000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/i686/cmov/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\233\1\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0755, st_size=1742588, ...}) = 0
        mmap2(NULL, 1747580, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7487000
        mmap2(0xb762c000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a5000) = 0xb762c000
        mmap2(0xb762f000, 10876, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb762f000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0PK\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0644, st_size=153640, ...}) = 0
        mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7486000
        mmap2(NULL, 163088, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb745e000
        mmap2(0xb7483000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x24000) = 0xb7483000
        mmap2(0xb7485000, 3344, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7485000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/liblzma.so.5", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\34\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0644, st_size=165420, ...}) = 0
        mmap2(NULL, 164100, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7435000
        mmap2(0xb745b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x26000) = 0xb745b000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/libgcrypt.so.20", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 N\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0644, st_size=722964, ...}) = 0
        mmap2(NULL, 722284, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7384000
        mmap2(0xb7430000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xac000) = 0xb7430000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\20\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0644, st_size=460084, ...}) = 0
        mmap2(NULL, 459064, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7313000
        mmap2(0xb7382000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6f000) = 0xb7382000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/i686/cmov/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\n\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0644, st_size=13856, ...}) = 0
        mmap2(NULL, 16512, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb730e000
        mmap2(0xb7311000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0xb7311000
        close(3)                                = 0
        access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
        open("/lib/i386-linux-gnu/libgpg-error.so.0", O_RDONLY|O_CLOEXEC) = 3
        read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`\35\0\0004\0\0\0"..., 512) = 512
        fstat64(3, {st_mode=S_IFREG|0644, st_size=75296, ...}) = 0
        mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb730d000
        mmap2(NULL, 78108, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb72f9000
        mmap2(0xb730b000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11000) = 0xb730b000
        close(3)                                = 0
        mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb72f8000
        set_thread_area({entry_number:-1, base_addr:0xb72f8a00, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 (entry_number:6)
        mprotect(0xb762c000, 8192, PROT_READ)   = 0
        mprotect(0xb730b000, 4096, PROT_READ)   = 0
        mprotect(0xb7311000, 4096, PROT_READ)   = 0
        mprotect(0xb764a000, 4096, PROT_READ)   = 0
        mprotect(0xb7382000, 4096, PROT_READ)   = 0
        mprotect(0xb7430000, 8192, PROT_READ)   = 0
        mprotect(0xb745b000, 8192, PROT_READ)   = 0
        mprotect(0xb7483000, 4096, PROT_READ)   = 0
        mprotect(0xb773c000, 16384, PROT_READ)  = 0
        mprotect(0xb76af000, 4096, PROT_READ)   = 0
        munmap(0xb764e000, 247187)              = 0
        set_tid_address(0xb72f8a68)             = 5389
        set_robust_list(0xb72f8a70, 12)         = 0
        rt_sigaction(SIGRTMIN, {0xb7637800, [], SA_SIGINFO}, NULL, 8) = 0
        rt_sigaction(SIGRT_1, {0xb7637880, [], SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
        rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
        getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
        uname({sys="Linux", node="mattotaupa", ...}) = 0
        brk(0)                                  = 0xb8388000
        brk(0xb83a9000)                         = 0xb83a9000
        statfs64("/sys/fs/selinux", 84, 0xbfa901b8) = -1 ENOENT (No such file or directory)
        statfs64("/selinux", 84, 0xbfa901b8)    = -1 ENOENT (No such file or directory)
        open("/proc/filesystems", O_RDONLY|O_LARGEFILE) = 3
        fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
        mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb768a000
        read(3, "nodev\tsysfs\nnodev\trootfs\nnodev\tr"..., 1024) = 329
        read(3, "", 1024)                       = 0
        close(3)                                = 0
        munmap(0xb768a000, 4096)                = 0
        open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
        fstat64(3, {st_mode=S_IFREG|0644, st_size=1607808, ...}) = 0
        mmap2(NULL, 1607808, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb716f000
        close(3)                                = 0
        access("/proc/vz", F_OK)                = -1 ENOENT (No such file or directory)
        open("/run/systemd/container", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
        open("/proc/cmdline", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
        fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
        mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb768a000
        read(3, "BOOT_IMAGE=/vmlinuz-3.16.0-4-686"..., 1024) = 310
        close(3)                                = 0
        munmap(0xb768a000, 4096)                = 0
        ioctl(1, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
        stat64("/proc/1/root", 0xbfa900ac)      = -1 EACCES (Permission denied)
        stat64("/proc/1/root", 0xbfa9009c)      = -1 EACCES (Permission denied)
        lstat64("/run/systemd/system/", {st_mode=S_IFDIR|0755, st_size=40, ...}) = 0
        geteuid32()                             = 1000
        socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
        setsockopt(3, SOL_SOCKET, SO_PASSCRED, [0], 4) = 0
        setsockopt(3, SOL_SOCKET, 0x22 /* SO_??? */, [0], 4) = 0
        getsockopt(3, SOL_SOCKET, SO_RCVBUF, [163840], [4]) = 0
        setsockopt(3, SOL_SOCKET, 0x21 /* SO_??? */, [8388608], 4) = -1 EPERM (Operation not permitted)
        setsockopt(3, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0
        getsockopt(3, SOL_SOCKET, SO_SNDBUF, [163840], [4]) = 0
        setsockopt(3, SOL_SOCKET, 0x20 /* SO_??? */, [8388608], 4) = -1 EPERM (Operation not permitted)
        setsockopt(3, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0
        connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
        getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
        clock_gettime(CLOCK_MONOTONIC, {804, 602904735}) = 0
        fstat64(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
        getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
        getsockname(3, {sa_family=AF_LOCAL, NULL}, [2]) = 0
        geteuid32()                             = 1000
        sendmsg(3, {msg_name(0)=NULL, msg_iov(3)=[{"\0AUTH EXTERNAL ", 15}, {"31303030", 8}, {"\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", 28}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 51
        gettid()                                = 5389
        open("/dev/urandom", O_RDONLY|O_NOCTTY|O_LARGEFILE|O_CLOEXEC) = 4
        read(4, "\214\242\3123\335\244\352\365i\364\240\272\24>\367\321", 16) = 16
        close(4)                                = 0
        clock_gettime(CLOCK_MONOTONIC, {804, 603697469}) = 0
        stat64("/proc/1/root", 0xbfa900ac)      = -1 EACCES (Permission denied)
        clock_gettime(CLOCK_MONOTONIC, {804, 604318035}) = 0
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"OK f3777e1f158114153c4b92be5491e"..., 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
        clock_gettime(CLOCK_MONOTONIC, {804, 605561372}) = 0
        sendmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
        clock_gettime(CLOCK_MONOTONIC, {804, 605955264}) = 0
        recvmsg(3, 0xbfa8eb40, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
        clock_gettime(CLOCK_MONOTONIC, {804, 606096206}) = 0
        ppoll([{fd=3, events=POLLIN}], 1, {24, 997601000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {24, 994912781})
        clock_gettime(CLOCK_MONOTONIC, {804, 609076049}) = 0
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\n\0\0\0\1\0\0\0=\0\0\0\6\1s\0\5\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{":1.27\0\0\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0"..., 66}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 66
        sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\5\0\0\0\2\0\0\0\247\0\0\0\1\1o\0007\0\0\0/org/fre"..., 184}, {"\0\0\0\0\0", 5}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 189
        clock_gettime(CLOCK_MONOTONIC, {804, 610455116}) = 0
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\n\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0"..., 146}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 146
        recvmsg(3, 0xbfa8ec10, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
        clock_gettime(CLOCK_MONOTONIC, {804, 610972235}) = 0
        ppoll([{fd=3, events=POLLIN}], 1, {24, 999483000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {0, 0})
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\3\1\0015\0\0\0\3\0\0\0m\0\0\0\6\1s\0\5\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
        recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{":1.27\0\0\0\4\1s\0#\0\0\0org.freedesktop."..., 157}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 157
        writev(2, [{"Failed to get properties: Activa"..., 74}, {"\n", 1}], 2) = 75
        exit_group(1)                           = ?
        +++ exited with 1 +++

It returned with a time-out.

Any help is appreciated to solve this.

[1] https://bugs.freedesktop.org/show_bug.cgi?id=86431
Comment 1 Paul Menzel 2014-12-20 10:59:13 UTC 
Created attachment 111079 [details]
Output of `sudo journalctl -l -b -3`

As asked by smcv in #dbus@irc.freennode.net I am attaching the log.
Comment 2 Paul Menzel 2014-12-28 11:38:05 UTC 
Last time when `binfmt-support.service` did not start and the boot hung, running `htop` in the debug shell, it should that `/sbin/init` used around 40 % of the CPU. Attaching with GDB there is the backtrace below. No idea if that can be explained by the fact that systemd is waiting for D-Bus or something else.

Thread 1 (Thread 0xb72a77c0 (LWP 1)):
#0  0xb75b6d3c in __kernel_vsyscall ()
No symbol table info available.
#1  0xb749aebe in timerfd_settime () at ../sysdeps/unix/syscall-template.S:81
No locals.
#2  0xb761b49d in event_arm_timer.lto_priv.605 (e=e@entry=0xb85c8e90, d=d@entry=0xb85c8ed0) at ../src/libsystemd/sd-event/sd-event.c:1781
        its = {it_interval = {tv_sec = 0, tv_nsec = 0}, it_value = {tv_sec = 0, tv_nsec = 1}}
        a = <optimized out>
        b = <optimized out>
        t = 0
        r = <optimized out>
        __PRETTY_FUNCTION__ = "event_arm_timer"
#3  0xb760c78e in sd_event_run (e=<optimized out>, timeout=18446744073709551615) at ../src/libsystemd/sd-event/sd-event.c:2225
        ev_queue = <optimized out>
        ev_queue_max = <optimized out>
        p = <optimized out>
        r = <optimized out>
        i = <optimized out>
        m = <optimized out>
        timedout = <optimized out>
        __PRETTY_FUNCTION__ = "sd_event_run"
#4  0xb7697f13 in manager_loop (m=0xb85c8bd0) at ../src/core/manager.c:1912
        wait_usec = 18446744073709551615
        rl = {interval = 1000000, begin = 1278764232, burst = 50000, num = 43622}
        __PRETTY_FUNCTION__ = "manager_loop"
        __func__ = "manager_loop"
#5  0xb75eb062 in main (argc=1, argv=0xbf8b1c64) at ../src/core/main.c:1743
        m = <optimized out>
        r = <optimized out>
        retval = 1
        before_startup = <optimized out>
        after_startup = <optimized out>
        timespan = " \201*\267@[[\267\234\325U\267\070\324;\267\364\276U\267\001\000\000\000\000\000\000\000 T\\\267\330\032\213\277\000\220]\267\264\030\213\277 Z[\267p\030\213\277\352\"\\\267 \030\213\277\364\276U\267"
        fds = 0x0
        reexecute = false
        shutdown_verb = 0x0
        initrd_timestamp = <optimized out>
        userspace_timestamp = {realtime = 1419759906775553, monotonic = 44872499}
        kernel_timestamp = {realtime = <optimized out>, monotonic = 0}
        security_start_timestamp = {realtime = 1419759906824087, monotonic = 44921034}
        security_finish_timestamp = {realtime = 1419759906857197, monotonic = 44954144}
        systemd = "systemd"
        skip_setup = <optimized out>
        j = <optimized out>
        loaded_policy = false
        arm_reboot_watchdog = false
        queue_default_job = <optimized out>
        empty_etc = <optimized out>
        switch_root_dir = 0x0
        switch_root_init = 0x0
        saved_rlimit_nofile = {rlim_cur = 1024, rlim_max = 4096}
        __func__ = "main"
        __PRETTY_FUNCTION__ = "main"
Comment 3 Simon McVittie 2014-12-30 11:02:27 UTC 
(In reply to Paul Menzel from comment #2)
> Last time when `binfmt-support.service` did not start and the boot hung,
> running `htop` in the debug shell, it should that `/sbin/init` used around
> 40 % of the CPU.

Sorry, I think you'll need to talk to the systemd maintainers about this.
Comment 4 Paul Menzel 2014-12-30 14:38:11 UTC 
(In reply to Simon McVittie from comment #3)
> (In reply to Paul Menzel from comment #2)
> > Last time when `binfmt-support.service` did not start and the boot hung,
> > running `htop` in the debug shell, it should that `/sbin/init` used around
> > 40 % of the CPU.
> 
> Sorry, I think you'll need to talk to the systemd maintainers about this.

No problem. What do you mean by “this” though? The whole issue or the `binfmt-support.service` issue?
Comment 5 Simon McVittie 2015-01-27 12:02:13 UTC 
(In reply to Paul Menzel from comment #4)
> No problem. What do you mean by “this” though? The whole issue or the
> `binfmt-support.service` issue?

The whole issue:

> `/sbin/init` used around 40 % of the CPU

This seems like something that shouldn't happen.

> Dez 17 21:41:25 my-asrock-e350m1 systemd[1]: Looping too fast. Throttling execution a little.

So does this.
Comment 6 Simon McVittie 2015-11-17 15:13:14 UTC 
Sorry, I don't think dbus maintainers can help you with this.

See also https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=789796

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.