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

[Thierry Parmentelat]

> On 18 Feb 2015, at 18:47, Lennart Poettering <lennart at poettering.net> wrote:
> 
> 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

OK, I’ll do this next time the box enters that state

Thanks — Thierry