GNU bug report logs - #77401
[Shepherd] Timer spawns many commands on DST change (CET -> CEST)

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 77401 in the body.
You can then email your comments to 77401 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: bug-guix <at> gnu.org
Subject: [Shepherd] Timer spawns too many commands
Date: Mon, 31 Mar 2025 09:54:56 +0200

Something went wrong on berlin (Shepherd 1.0.3):

--8<---------------cut here---------------start------------->8---
2025-03-29 22:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 45159.
2025-03-29 22:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-29 22:15:04 localhost shepherd[1]: Process 45159 of timer 'update-guix.gnu.org' terminated with status 0 after 4 seconds.
[...]
2025-03-29 23:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 38952.
2025-03-29 23:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-29 23:15:03 localhost shepherd[1]: Process 38952 of timer 'update-guix.gnu.org' terminated with status 0 after 3 seconds.
[...]
2025-03-30 00:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 32759.
2025-03-30 00:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 00:15:04 localhost shepherd[1]: Process 32759 of timer 'update-guix.gnu.org' terminated with status 0 after 4 seconds.
[...]
2025-03-30 01:14:12 localhost ntpd[1829]: Soliciting pool server 185.197.135.21
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51571.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51572.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51579.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51605.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51622.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51639.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51650.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51673.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51690.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51707.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51725.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51728.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51760.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51778.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51795.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51798.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51830.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
[...]
2025-03-30 01:15:01 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 03:00:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 53303.
2025-03-30 03:00:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
[...]
2025-03-30 03:00:06 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 53334.
2025-03-30 03:00:07 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 03:00:07 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 53351.
2025-03-30 03:00:07 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:07 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:09 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:09 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:10 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:10 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:10 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
[...]
2025-03-30 03:01:23 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep st
2025-03-30 03:01:23 localhost shepherd[1]: ate?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sl
2025-03-30 03:01:23 localhost shepherd[1]: eep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming f
2025-03-30 03:01:23 localhost shepherd[1]: rom sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resu
--8<---------------cut here---------------end--------------->8---

The “waiting anew” bit could be related to the DST change, but things
went wrong before the DST change, at 1:15AM.

FWIW, the service had #:wait-for-termination? #false.

Ludo’.

Message #14 received at 77401-done <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Timo Wilken" <guix <at> twilken.net>
Cc: 77401-done <at> debbugs.gnu.org, 77390-done <at> debbugs.gnu.org
Subject: Re: bug#77401: [Shepherd] Timer spawns too many commands
Date: Mon, 31 Mar 2025 23:21:56 +0200

Hi Timo,

"Timo Wilken" <guix <at> twilken.net> skribis:

> Last night, this hit the exact moment of the CET/CEST change and seems to have
> confused the Shepherd a lot, to the point where it kept spamming the same
> message to /var/log/messages, and used up 80% of my system's total memory,
> according to htop. (This led to various things getting oom-killed, and the
> system grinding to a halt until I had a look at it in the afternoon.)
>
> First, at 01:00, the Shepherd spawned about 30 processes for this one timer:

This is now fixed:

  https://git.savannah.gnu.org/cgit/shepherd.git/commit/?id=b36e97a730596dbf3c376f940150d5fd1f08ecf1

Let me know if you find something fishy.

The irony is that the work I did for <https://issues.guix.gnu.org/75622>
helped, but the one test that would have caught this issue was wrong: it
was looking at the wrong date when testing the CET->CEST change.

Setting #:wait-for-termination? #true would have mitigated this bug (it
wouldn’t have triggered).

Thanks,
Ludo’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.