Subject: Shepherd: bug in timer scheduling on daylight savings time change
From: "Timo Wilken" <[email-masked]>
To: <[email-masked]>
Date: Sun, 30 Mar 2025 22:04:07 +0200
List-Id: <debbugs-submit.debbugs.gnu.org>

Hi,

Last night, my server's time changed from CET to CEST automatically, as it is
set to Europe/Berlin time.

I have a Shepherd timer set to run every night at 02:00 local time:
https://cgit.twilken.net/dotfiles/tree/tw/system.scm?h=cd39f5d3340c0bcd59bb80d3ff4f12741db75e07#n136

--8<---------------cut here
   (simple-service 'disk-maintenance shepherd-root-service-type
     (list (shepherd-service
            (provision '(guix-gc))
            (requirement '(user-processes file-systems))
            (documentation "Delete unused files from Guix' store.")
            (modules '((shepherd service timer)))
            (start #~(make-timer-constructor
                      (calendar-event #:hours '(2) #:minutes '(0))
                      (command (list "guix" "gc" "-d" "2w"))))
            (stop #~(make-timer-destructor))
            (actions (list (shepherd-action
                            (name 'trigger) (procedure #~trigger-timer)
                            (documentation "Collect garbage now.")))))))
--8<---------------cut here

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:

--8<---------------cut here
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1691.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'nextcloud-cron' spawned process 1692.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for nextcloud-cron.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'gpsplot' spawned process 1693.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for gpsplot.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'dynamic-dns-ipv4.api.mythic-beasts.com' spawned process 1694.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for dynamic-dns-ipv4.api.mythic-beasts.com.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1698.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1703.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1713.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1715.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1723.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1726.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1732.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1736.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1740.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1750.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1754.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1761.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1766.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1768.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1778.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1785.
2025-03-30 01:00:00 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:00 localhost shepherd[1]: Timer 'guix-gc' spawned process 1791.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1806.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1811.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1818.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1822.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1829.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1838.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1848.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1851.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1862.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1872.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1876.
2025-03-30 01:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 01:00:02 localhost shepherd[1]: Timer 'guix-gc' spawned process 1883.
2025-03-30 01:00:02 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 03:00:00 localhost linux: [46479.948177] perf: interrupt took too long (2504 > 2500), lowering kernel.perf_event_max_sample_rate to 79750
2025-03-30 03:00:01 localhost linux: [47490.137060] perf: interrupt took too long (3138 > 3130), lowering kernel.perf_event_max_sample_rate to 63500
2025-03-30 03:00:01 localhost shepherd[1]: Timer 'guix-gc' spawned process 1887.
2025-03-30 03:00:01 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 03:00:02 localhost shepherd[1]: Timer 'guix-gc' spawned process 1896.
2025-03-30 03:00:02 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 03:00:03 localhost shepherd[1]: Timer 'guix-gc' spawned process 1910.
2025-03-30 03:00:03 localhost shepherd[1]: Registering new logger for guix-gc.
2025-03-30 03:00:03 localhost shepherd[1]: Timer 'guix-gc' spawned process 1915.
--8<---------------cut here

I then get 731(!!) lines like the following over the course of 3 seconds:

--8<---------------cut here
2025-03-30 03:00:03 localhost shepherd[1]: Waiting anew for timer 'guix-gc' (resuming from sleep state?).
[...]
2025-03-30 03:00:06 localhost shepherd[1]: Waiting anew for timer 'guix-gc' (resuming from sleep state?).
--8<---------------cut here

The Shepherd then gets more confused and starts spamming the same message over
and over again, but now without newlines, leading to lines like:

--8<---------------cut here
2025-03-30 03:00:06 localhost shepherd[1]: Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for
2025-03-30 03:00:06 localhost shepherd[1]:  timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc' (resuming from sleep state?).Waiting anew for timer 'guix-gc'
--8<---------------cut here

Then there's some output from the various "guix gc" processes spawned by the
timer, which of course all step on each other's toes. The Shepherd keeps
happily writing the above lines out in large blocks.

It goes on like this until the afternoon, when the OOM kills start (probably
when I start SSH'ing in to see what's going on):

--8<---------------cut here
2025-03-30 15:21:44 localhost linux: [93869.155828] sshd-session invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
--8<---------------cut here

After a bit of that, I decide to reboot the machine.

I've saved the system logs from that night - let me know if you need more details.

I'm running Shepherd 1.0.3, as packaged in Guix:

--8<---------------cut here
Generation 235	Mar 29 2025 12:07:15	(current)
  file name: /var/guix/profiles/system-235-link
  canonical file name: /gnu/store/p7infvmm678nysvdg3xvxlr83xxkj66j-system
  label: GNU with Linux-Libre 6.13.8
  bootloader: grub-efi
  root device: UUID: c63af3e6-3c2b-43d2-b1e6-944f09a10e0f
  kernel: /gnu/store/d7z9027yrs1vfmpvds10iqfl69cyvixn-linux-libre-6.13.8/bzImage
  channels:
    tw:
      repository URL: https://git.twilken.net/dotfiles
      branch: master
      commit: 39abf96d68ce500abbd55f9bdbd68e1c63282d36
    guix:
      repository URL: https://git.savannah.gnu.org/git/guix.git
      branch: master
      commit: 67f4a2feadbb6cc04a61b5a3bc7b8f4bace2a0bb
    [non-free channels omitted]
--8<---------------cut here

Cheers,
Timo