[systemd-devel] Looping too fast. Throttling execution a little

[Lennart Poettering]

On Wed, 18.02.15 10:41, Thierry Parmentelat (thierry.parmentelat at inria.fr) wrote:

> root at bigjohn /vservers # journalctl -b -f
> -- Logs begin at Fri 2014-09-05 04:28:57 CEST. --
> Feb 18 10:38:25 bigjohn.pl.sophia.inria.fr systemd[1]: Looping too fast. Throttling execution a little.
> Feb 18 10:38:26 bigjohn.pl.sophia.inria.fr systemd[1]: Looping too fast. Throttling execution a little.
> Feb 18 10:38:28 bigjohn.pl.sophia.inria.fr systemd[1]: Looping too fast. Throttling execution a little.
> Feb 18 10:38:30 bigjohn.pl.sophia.inria.fr systemd[1]: Looping too fast. Throttling execution a little.
> Feb 18 10:38:31 bigjohn.pl.sophia.inria.fr systemd[1]: Looping too fast. Throttling execution a little.
> Feb 18 10:38:33 bigjohn.pl.sophia.inria.fr systemd[1]: Looping too fast. Throttling execution a little.

THis is happens if for some reason the event loop entered a busy
loop. It's simply a protection against eating up all CPU forever. It's
a symptom of another bug, which is the one to track down.

> # strace -p 1 
> <…>
> recvmsg(42, 0x7fff3ea64d00, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
> timerfd_settime(3, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={0, 1}}, NULL) = 0
> epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 36, 0) = 1
> clock_gettime(CLOCK_BOOTTIME, {1959524, 957887776}) = 0
> read(3, "\1\0\0\0\0\0\0\0", 8)          = 8
> recvmsg(42, 0x7fff3ea64d00, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
> timerfd_settime(3, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={0, 1}}, NULL) = 0
> epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 36, 0) = 1
> clock_gettime(CLOCK_BOOTTIME, {1959524, 958282696}) = 0
> read(3, "\1\0\0\0\0\0\0\0", 8)          = 8
> recvmsg(42, 0x7fff3ea64d00, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
> timerfd_settime(3, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={0, 1}}, NULL) = 0
> epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 36, 0) = 1
> clock_gettime(CLOCK_BOOTTIME, {1959524, 958617432}) = 0
> ^CProcess 1 detached

Hmm, this appears to be caused by a timer that is not reset. First the
timer fd is set to the earliest possible trigger, then epoll_wait() is
entered, which immediately quites. Then the tiemrfd elapse counter is
read which is 1.

It would be interesting to figure out which timer this is.

To make this work, can you reproduce the issue, then use gdb:

1. Type "gdb" to start it
2. Type "attach 1" to attach to PID 1
3. Type "b source_dispatch" to set a break point on the source_dispatch function
4. Type "c" to continue execution
5. This should then break on the next execution of the source_dispatch function
6. This should happen immediately, after all PID 1 is busy looping
   around a timer. Use "p s->description" to get a short description
   string for the event that is being dispatched. In fact, please use
   "p *s" to get all data about the event, and paste it here.

Thanks!

Lennart

-- 
Lennart Poettering, Red Hat