[systemd-devel] Looping too fast. Throttling execution a little
John Morrissey
jwm at horde.net
Tue Apr 28 16:25:34 PDT 2015
On 18 Feb 2015, at 18:47, Lennart Poettering <lennart at poettering.net> wrote:
> 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.
I noticed this behavior recently on a Debian jessie system running systemd
215-17. systemd got itself in a loop like the previous reporter's:
--
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)
--
and became pretty much unresponsive (daemon restarts took minutes, if they
ever completed, etc.).
Here's the gdb output; there's no description on the variable in question,
so I had gdb emit all struct members for several loop iterations:
(gdb) p s->description
There is no member named description.
(gdb) p *s
$1 = {n_ref = 1, event = 0x100007f85, userdata = 0x7f85414b4bf0, prepare = 0x0,
type = -16, enabled = 2, pending = false, dispatching = false, floating = false,
priority = 8455620127265646592, pending_index = 1, prepare_index = 0,
pending_iteration = 1095177008, prepare_iteration = 32645, sources_next = 0x1,
sources_prev = 0x7f8540dae40e, {io = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, fd = 1095414960, events = 32645,
revents = 1, registered = false}, time = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, next = 140210302792880,
accuracy = 1, earliest_index = 1087651621, latest_index = 32645}, signal = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
ssi_signo = 1095414960, ssi_errno = 32645, ssi_code = 1, ssi_pid = 0,
ssi_uid = 1087651621, ssi_fd = 32645, ssi_tid = 1095177008, ssi_band = 32645,
ssi_overrun = 1087684037, ssi_trapno = 32645, ssi_status = 1086746592,
ssi_int = 32645, ssi_ptr = 140731408831079, ssi_utime = 140731408830816,
ssi_stime = 0, ssi_addr = 140731408830848,
__pad = "0\aKA\205\177\000\000\260\264JA\205\177\000\000\tWY@\205\177\000\000\000\000\000\000\000\000\000\000\224UY@\205\177\000\000\000\000\000\000\000\000\000"},
sig = 465584131}, child = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>,
siginfo = {si_signo = 1095414960, si_errno = 32645, si_code = 1, _sifields = {
_pad = {1087651621, 32645, 1095177008, 32645, 1087684037, 32645, 1086746592,
32645, -1784556953, 32766, -1784557216, 32766, 0, 0, -1784557184, 32766,
1095436080, 32645, 1095414960, 32645, 1079596809, 32645, 0, 0, 1079596436,
32645, 0, 0}, _kill = {si_pid = 1087651621, si_uid = 32645}, _timer = {
si_tid = 1087651621, si_overrun = 32645, si_sigval = {
sival_int = 1095177008, sival_ptr = 0x7f8541471330}}, _rt = {
si_pid = 1087651621, si_uid = 32645, si_sigval = {sival_int = 1095177008,
sival_ptr = 0x7f8541471330}}, _sigchld = {si_pid = 1087651621,
si_uid = 32645, si_status = 1095177008, si_utime = 140210295061957,
si_stime = 140210294124512}, _sigfault = {
si_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>, si_addr_lsb = 4912},
_sigpoll = {si_band = 140210295029541, si_fd = 1095177008}, _sigsys = {
_call_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>,
_syscall = 1095177008, _arch = 32645}}}, pid = 465584131, options = 0},
defer = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, post = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, exit = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, prioq_index = 1095414960}}}
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x7ffe95a1d080)
at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
$2 = {n_ref = 1, event = 0x100007f85, userdata = 0x7f85414b4bf0, prepare = 0x0,
type = -16, enabled = 2, pending = false, dispatching = false, floating = false,
priority = 8455620127265646592, pending_index = 1, prepare_index = 0,
pending_iteration = 1095177008, prepare_iteration = 32645, sources_next = 0x1,
sources_prev = 0x7f8540dae40e, {io = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, fd = 1095414960, events = 32645,
revents = 1, registered = false}, time = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, next = 140210302792880,
accuracy = 1, earliest_index = 1087651621, latest_index = 32645}, signal = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
ssi_signo = 1095414960, ssi_errno = 32645, ssi_code = 1, ssi_pid = 0,
ssi_uid = 1087651621, ssi_fd = 32645, ssi_tid = 1095177008, ssi_band = 32645,
ssi_overrun = 1087684037, ssi_trapno = 32645, ssi_status = 1086746592,
ssi_int = 32645, ssi_ptr = 140731408831079, ssi_utime = 140731408830816,
ssi_stime = 0, ssi_addr = 140731408830848,
__pad = "0\aKA\205\177\000\000\260\264JA\205\177\000\000\tWY@\205\177\000\000\000\000\000\000\000\000\000\000\224UY@\205\177\000\000\000\000\000\000\000\000\000"},
sig = 0}, child = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
si_signo = 1095414960, si_errno = 32645, si_code = 1, _sifields = {_pad = {
1087651621, 32645, 1095177008, 32645, 1087684037, 32645, 1086746592, 32645,
-1784556953, 32766, -1784557216, 32766, 0, 0, -1784557184, 32766,
1095436080, 32645, 1095414960, 32645, 1079596809, 32645, 0, 0, 1079596436,
32645, 0, 0}, _kill = {si_pid = 1087651621, si_uid = 32645}, _timer = {
si_tid = 1087651621, si_overrun = 32645, si_sigval = {
sival_int = 1095177008, sival_ptr = 0x7f8541471330}}, _rt = {
si_pid = 1087651621, si_uid = 32645, si_sigval = {sival_int = 1095177008,
sival_ptr = 0x7f8541471330}}, _sigchld = {si_pid = 1087651621,
si_uid = 32645, si_status = 1095177008, si_utime = 140210295061957,
si_stime = 140210294124512}, _sigfault = {
si_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>, si_addr_lsb = 4912},
_sigpoll = {si_band = 140210295029541, si_fd = 1095177008}, _sigsys = {
_call_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>,
_syscall = 1095177008, _arch = 32645}}}, pid = 0, options = 0}, defer = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, post = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, exit = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, prioq_index = 1095414960}}}
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x0) at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
Cannot access memory at address 0x0
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x7ffe95a1d080)
at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
$3 = {n_ref = 1, event = 0x100007f85, userdata = 0x7f85414b4bf0, prepare = 0x0,
type = -16, enabled = 2, pending = false, dispatching = false, floating = false,
priority = 8455620127265646592, pending_index = 1, prepare_index = 0,
pending_iteration = 1095177008, prepare_iteration = 32645, sources_next = 0x1,
sources_prev = 0x7f8540dae40e, {io = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, fd = 1095414960, events = 32645,
revents = 1, registered = false}, time = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, next = 140210302792880,
accuracy = 1, earliest_index = 1087651621, latest_index = 32645}, signal = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
ssi_signo = 1095414960, ssi_errno = 32645, ssi_code = 1, ssi_pid = 0,
ssi_uid = 1087651621, ssi_fd = 32645, ssi_tid = 1095177008, ssi_band = 32645,
ssi_overrun = 1087684037, ssi_trapno = 32645, ssi_status = 1086746592,
ssi_int = 32645, ssi_ptr = 140731408831079, ssi_utime = 140731408830816,
ssi_stime = 0, ssi_addr = 140731408830848,
__pad = "0\aKA\205\177\000\000\260\264JA\205\177\000\000\tWY@\205\177\000\000\000\000\000\000\000\000\000\000\224UY@\205\177\000\000\000\000\000\000\000\000\000"},
sig = 0}, child = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
si_signo = 1095414960, si_errno = 32645, si_code = 1, _sifields = {_pad = {
1087651621, 32645, 1095177008, 32645, 1087684037, 32645, 1086746592, 32645,
-1784556953, 32766, -1784557216, 32766, 0, 0, -1784557184, 32766,
1095436080, 32645, 1095414960, 32645, 1079596809, 32645, 0, 0, 1079596436,
32645, 0, 0}, _kill = {si_pid = 1087651621, si_uid = 32645}, _timer = {
si_tid = 1087651621, si_overrun = 32645, si_sigval = {
sival_int = 1095177008, sival_ptr = 0x7f8541471330}}, _rt = {
si_pid = 1087651621, si_uid = 32645, si_sigval = {sival_int = 1095177008,
sival_ptr = 0x7f8541471330}}, _sigchld = {si_pid = 1087651621,
si_uid = 32645, si_status = 1095177008, si_utime = 140210295061957,
si_stime = 140210294124512}, _sigfault = {
si_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>, si_addr_lsb = 4912},
_sigpoll = {si_band = 140210295029541, si_fd = 1095177008}, _sigsys = {
_call_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>,
_syscall = 1095177008, _arch = 32645}}}, pid = 0, options = 0}, defer = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, post = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, exit = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, prioq_index = 1095414960}}}
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x0) at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
Cannot access memory at address 0x0
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x7ffe95a1d080)
at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
$4 = {n_ref = 1, event = 0x100000000, userdata = 0x7f85414b4bf0, prepare = 0x0,
type = -16, enabled = 2, pending = false, dispatching = false, floating = false,
priority = 8455620127265646592, pending_index = 1, prepare_index = 0,
pending_iteration = 1095177008, prepare_iteration = 32645, sources_next = 0x1,
sources_prev = 0x7f8540dae40e, {io = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, fd = 1095414960, events = 32645,
revents = 1, registered = false}, time = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, next = 140210302792880,
accuracy = 1, earliest_index = 1087651621, latest_index = 32645}, signal = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
ssi_signo = 1095414960, ssi_errno = 32645, ssi_code = 1, ssi_pid = 0,
ssi_uid = 1087651621, ssi_fd = 32645, ssi_tid = 1095177008, ssi_band = 32645,
ssi_overrun = 1087684037, ssi_trapno = 32645, ssi_status = 1086746592,
ssi_int = 32645, ssi_ptr = 140731408831079, ssi_utime = 140731408830816,
ssi_stime = 0, ssi_addr = 140731408830848,
__pad = "0\aKA\205\177\000\000\260\264JA\205\177\000\000\tWY@\205\177\000\000\000\000\000\000\000\000\000\000\224UY@\205\177\000\000\000\000\000\000\000\000\000"},
sig = 0}, child = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
si_signo = 1095414960, si_errno = 32645, si_code = 1, _sifields = {_pad = {
1087651621, 32645, 1095177008, 32645, 1087684037, 32645, 1086746592, 32645,
-1784556953, 32766, -1784557216, 32766, 0, 0, -1784557184, 32766,
1095436080, 32645, 1095414960, 32645, 1079596809, 32645, 0, 0, 1079596436,
32645, 0, 0}, _kill = {si_pid = 1087651621, si_uid = 32645}, _timer = {
si_tid = 1087651621, si_overrun = 32645, si_sigval = {
sival_int = 1095177008, sival_ptr = 0x7f8541471330}}, _rt = {
si_pid = 1087651621, si_uid = 32645, si_sigval = {sival_int = 1095177008,
sival_ptr = 0x7f8541471330}}, _sigchld = {si_pid = 1087651621,
si_uid = 32645, si_status = 1095177008, si_utime = 140210295061957,
si_stime = 140210294124512}, _sigfault = {
si_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>, si_addr_lsb = 4912},
_sigpoll = {si_band = 140210295029541, si_fd = 1095177008}, _sigsys = {
_call_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>,
_syscall = 1095177008, _arch = 32645}}}, pid = 0, options = 0}, defer = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, post = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, exit = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, prioq_index = 1095414960}}}
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x7ffe95a1d080)
at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
$5 = {n_ref = 1, event = 0x100000000, userdata = 0x7f85414b4bf0, prepare = 0x0,
type = -16, enabled = 2, pending = false, dispatching = false, floating = false,
priority = 8455620127265646592, pending_index = 1, prepare_index = 0,
pending_iteration = 1095177008, prepare_iteration = 32645, sources_next = 0x1,
sources_prev = 0x7f8540dae40e, {io = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, fd = 1095414960, events = 32645,
revents = 1, registered = false}, time = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, next = 140210302792880,
accuracy = 1, earliest_index = 1087651621, latest_index = 32645}, signal = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
ssi_signo = 1095414960, ssi_errno = 32645, ssi_code = 1, ssi_pid = 0,
ssi_uid = 1087651621, ssi_fd = 32645, ssi_tid = 1095177008, ssi_band = 32645,
ssi_overrun = 1087684037, ssi_trapno = 32645, ssi_status = 1086746592,
ssi_int = 32645, ssi_ptr = 140731408831079, ssi_utime = 140731408830816,
ssi_stime = 0, ssi_addr = 140731408830848,
__pad = "0\aKA\205\177\000\000\260\264JA\205\177\000\000\tWY@\205\177\000\000\000\000\000\000\000\000\000\000\224UY@\205\177\000\000\000\000\000\000\000\000\000"},
sig = 0}, child = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
si_signo = 1095414960, si_errno = 32645, si_code = 1, _sifields = {_pad = {
1087651621, 32645, 1095177008, 32645, 1087684037, 32645, 1086746592, 32645,
-1784556953, 32766, -1784557216, 32766, 0, 0, -1784557184, 32766,
1095436080, 32645, 1095414960, 32645, 1079596809, 32645, 0, 0, 1079596436,
32645, 0, 0}, _kill = {si_pid = 1087651621, si_uid = 32645}, _timer = {
si_tid = 1087651621, si_overrun = 32645, si_sigval = {
sival_int = 1095177008, sival_ptr = 0x7f8541471330}}, _rt = {
si_pid = 1087651621, si_uid = 32645, si_sigval = {sival_int = 1095177008,
sival_ptr = 0x7f8541471330}}, _sigchld = {si_pid = 1087651621,
si_uid = 32645, si_status = 1095177008, si_utime = 140210295061957,
si_stime = 140210294124512}, _sigfault = {
si_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>, si_addr_lsb = 4912},
_sigpoll = {si_band = 140210295029541, si_fd = 1095177008}, _sigsys = {
_call_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>,
_syscall = 1095177008, _arch = 32645}}}, pid = 0, options = 0}, defer = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, post = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, exit = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, prioq_index = 1095414960}}}
(gdb) cont
Continuing.
Breakpoint 1, source_dispatch (s=0x7ffe95a1d080)
at ../src/libsystemd/sd-event/sd-event.c:1976
1976 in ../src/libsystemd/sd-event/sd-event.c
(gdb) p *s
$6 = {n_ref = 1, event = 0x100000000, userdata = 0x7f85414b4bf0, prepare = 0x0,
type = -16, enabled = 2, pending = false, dispatching = false, floating = false,
priority = 8455620127265646592, pending_index = 1, prepare_index = 0,
pending_iteration = 1095177008, prepare_iteration = 32645, sources_next = 0x1,
sources_prev = 0x7f8540dae40e, {io = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, fd = 1095414960, events = 32645,
revents = 1, registered = false}, time = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, next = 140210302792880,
accuracy = 1, earliest_index = 1087651621, latest_index = 32645}, signal = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
ssi_signo = 1095414960, ssi_errno = 32645, ssi_code = 1, ssi_pid = 0,
ssi_uid = 1087651621, ssi_fd = 32645, ssi_tid = 1095177008, ssi_band = 32645,
ssi_overrun = 1087684037, ssi_trapno = 32645, ssi_status = 1086746592,
ssi_int = 32645, ssi_ptr = 140731408831079, ssi_utime = 140731408830816,
ssi_stime = 0, ssi_addr = 140731408830848,
__pad = "0\aKA\205\177\000\000\260\264JA\205\177\000\000\tWY@\205\177\000\000\000\000\000\000\000\000\000\000\224UY@\205\177\000\000\000\000\000\000\000\000\000"},
sig = 0}, child = {callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, siginfo = {
si_signo = 1095414960, si_errno = 32645, si_code = 1, _sifields = {_pad = {
1087651621, 32645, 1095177008, 32645, 1087684037, 32645, 1086746592, 32645,
-1784556953, 32766, -1784557216, 32766, 0, 0, -1784557184, 32766,
1095436080, 32645, 1095414960, 32645, 1079596809, 32645, 0, 0, 1079596436,
32645, 0, 0}, _kill = {si_pid = 1087651621, si_uid = 32645}, _timer = {
si_tid = 1087651621, si_overrun = 32645, si_sigval = {
sival_int = 1095177008, sival_ptr = 0x7f8541471330}}, _rt = {
si_pid = 1087651621, si_uid = 32645, si_sigval = {sival_int = 1095177008,
sival_ptr = 0x7f8541471330}}, _sigchld = {si_pid = 1087651621,
si_uid = 32645, si_status = 1095177008, si_utime = 140210295061957,
si_stime = 140210294124512}, _sigfault = {
si_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>, si_addr_lsb = 4912},
_sigpoll = {si_band = 140210295029541, si_fd = 1095177008}, _sigsys = {
_call_addr = 0x7f8540d43f25 <sd_bus_message_unref+37>,
_syscall = 1095177008, _arch = 32645}}}, pid = 0, options = 0}, defer = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, post = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>}, exit = {
callback = 0x7f8540ff3850 <bus_unit_vtable+3600>, prioq_index = 1095414960}}}
(gdb) quit
-john
More information about the systemd-devel
mailing list