Slow Shutdown in Puppy with Wayland

For some reason, poweroff in Puppy takes a very very long time.

Puppy replaces the poweroff executable (normally, a symlink to busybox) with a script. This way, it can hook the shutdown process and do some extra steps, like saving files in RAM back to the flash drive before the system shuts down. All these goodies happen inside /etc/rc.d/rc.shutdown:

 /etc/rc.d/rc.shutdown <=
 
 case $script in
 	poweroff) 
 	
 	 if [ $can_shutdown -eq 1 ]; then
 	  /bin/busybox poweroff
 	 else
 	  clear > /dev/console
 	  dialog --ok-label "Restart" --msgbox "IT'S NOW SAFE TO TURN OFF YOUR COMPUTER" 5 43
 	  /bin/busybox reboot
 	 fi
 	
 	;;
 	
 	reboot) /bin/busybox reboot ;;
 esac

poweroff, line 48

But you can't just bash -x /etc/rc.d/rc.shutdown to see why it takes so long, because it has this magic block:

 if [ ! -f /tmp/debugshutdown ] ; then
 	clear
 	exec 1> /dev/null 2>&1
 fi

rc.shutdown, line 20

Let's try to create this magic file then, and see what /etc/rc.d/rc.shutdown does:

 ~$ touch /tmp/debugshutdown
 ~$ bash -x /etc/rc.d/rc.shutdown > /tmp/log 2>&1

Oh no! The log is empty and the redirection doesn't work. How can it be? The answer is in line 9:

 [ -f /tmp/debugshutdown ] && exec &>/dev/console

rc.shutdown, line 9

/tmp/debugshutdown lets you choose between output you can't grep or redirect to a file, or no output at all. This makes it useless as a debugging tool, as the name suggests.

Once line 9 is deleted (only for the sake of debugging), it's easy to see that rc.shutdown hangs when it tries to stop seatd:

 ~$ bash -x /etc/rc.d/rc.shutdown
 .
 .
 .
 + /etc/init.d/seatd stop

This happens because the init script waits for start-stop-daemon, which takes a very long time:

 ~$ ps aux | grep seatd
 root        3053  0.0  0.0   2860  1096 ?        S    17:01   0:00 /usr/sbin/seatd
 root        4110  0.0  0.1   6572  2236 pts/1    S+   17:01   0:00 grep seatd
 ~$ bash -x /etc/init.d/seatd stop
 .
 .
 .
 + do_stop
 + start-stop-daemon --stop --quiet --retry=TERM/30/KILL/5 --pidfile /var/run/seatd.pid --name seatd
 + RETVAL=1
 + '[' 1 = 2 ']'
 + start-stop-daemon --stop --quiet --oknodo --retry=0/30/KILL/5 --exec /usr/sbin/seatd

Now, let's see why start-stop-daemon takes so long. It's not a shell script, so we'll use the venerable strace to see what it does. I'm often surprised when people rush to find a debugger, install debugging symbols for dependencies, recompile the application with -g, find a way to attach to a running process without killing it, etc', when a tool like strace is such a perfect fit for syscall-oriented problems, like processes that get stuck waiting for something. It's so easy to use, and very effective.

Back to debugging! It looks like start-stop-daemon is stuck in a loop:

 ~$ strace start-stop-daemon --stop --quiet --oknodo --retry=0/30/KILL/5 --exec /usr/sbin/seatd
 .
 .
 .
 4384  readlink("/proc/4363/exe", "/usr/sbin/seatd", 256) = 15
 4384  newfstatat(AT_FDCWD, "/usr/sbin/seatd", {st_mode=S_IFREG|0755, st_size=47504, ...}, 0) = 0
 .
 .
 .
 4384  kill(4363, 0)                     = 0
 4384  pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=33284000}, {sigmask=NULL, sigsetsize=8}) = 0 (Timeout)
 .
 .
 .

It uses polling to wait for seatd to terminate:

If signal is 0, then no actual signal is sent, but error checking is still performed.

kill(2)

But why is seatd still running? It looks like there is some bug here. I'm not sure where it is, but I see two likely options:

This doesn't matter really, because Puppy doesn't have logind. A wlroots-based compositor that talks to seatd via libseat eventually falls back to libseat's "builtin" backend, where libseat itself takes care of seat management without relying on seatd or logind. Puppy doesn't need the seatd daemon in first place, so the solution is to disable it: this solves the slow shutdown problem and reduces the number of running processes, which is always good.

Now, the process list with a fullscreen Xwayland, JWM, PCManFM (with desktop icons), Blueman and the traditional set of tray icons, under a patched dwl-based compositor, looks like this:

 USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 root           1  1.8  0.0   3792  1320 ?        Ss   17:23   0:01 /bin/busybox init
 root           2  0.0  0.0      0     0 ?        S    17:23   0:00 [kthreadd]
 root           3  0.0  0.0      0     0 ?        I<   17:23   0:00 [rcu_gp]
 root           4  0.0  0.0      0     0 ?        I<   17:23   0:00 [rcu_par_gp]
 root           5  0.0  0.0      0     0 ?        I<   17:23   0:00 [netns]
 root           6  0.0  0.0      0     0 ?        I    17:23   0:00 [kworker/0:0-events]
 root           7  0.0  0.0      0     0 ?        I<   17:23   0:00 [kworker/0:0H-events_highpri]
 root           8  1.2  0.0      0     0 ?        I    17:23   0:00 [kworker/u2:0-events_unbound]
 root           9  0.0  0.0      0     0 ?        I<   17:23   0:00 [mm_percpu_wq]
 root          10  0.0  0.0      0     0 ?        S    17:23   0:00 [rcu_tasks_rude_]
 root          11  0.0  0.0      0     0 ?        S    17:23   0:00 [rcu_tasks_trace]
 root          12  0.3  0.0      0     0 ?        S    17:23   0:00 [ksoftirqd/0]
 root          13  3.1  0.0      0     0 ?        I    17:23   0:01 [rcu_sched]
 root          14  0.0  0.0      0     0 ?        S    17:23   0:00 [migration/0]
 root          15  0.0  0.0      0     0 ?        S    17:23   0:00 [idle_inject/0]
 root          16  0.7  0.0      0     0 ?        I    17:23   0:00 [kworker/0:1-events]
 root          17  0.0  0.0      0     0 ?        S    17:23   0:00 [cpuhp/0]
 root          18  0.0  0.0      0     0 ?        S    17:23   0:00 [kdevtmpfs]
 root          19  0.0  0.0      0     0 ?        I<   17:23   0:00 [inet_frag_wq]
 root          20  0.0  0.0      0     0 ?        S    17:23   0:00 [kauditd]
 root          21  0.0  0.0      0     0 ?        S    17:23   0:00 [khungtaskd]
 root          22  0.0  0.0      0     0 ?        S    17:23   0:00 [oom_reaper]
 root          23  0.0  0.0      0     0 ?        I<   17:23   0:00 [writeback]
 root          24  0.0  0.0      0     0 ?        S    17:23   0:00 [kcompactd0]
 root          25  0.0  0.0      0     0 ?        SN   17:23   0:00 [ksmd]
 root          26  0.0  0.0      0     0 ?        SN   17:23   0:00 [khugepaged]
 root          78  0.0  0.0      0     0 ?        I<   17:23   0:00 [kintegrityd]
 root          79  0.0  0.0      0     0 ?        I<   17:23   0:00 [kblockd]
 root          80  0.0  0.0      0     0 ?        I<   17:23   0:00 [blkcg_punt_bio]
 root          81  0.0  0.0      0     0 ?        I<   17:23   0:00 [tpm_dev_wq]
 root          82  0.0  0.0      0     0 ?        I<   17:23   0:00 [tifm]
 root          83  0.0  0.0      0     0 ?        I<   17:23   0:00 [ata_sff]
 root          84  0.0  0.0      0     0 ?        I<   17:23   0:00 [md]
 root          85  0.0  0.0      0     0 ?        I<   17:23   0:00 [edac-poller]
 root          86  0.0  0.0      0     0 ?        I<   17:23   0:00 [devfreq_wq]
 root          87  0.0  0.0      0     0 ?        S    17:23   0:00 [watchdogd]
 root          88  0.3  0.0      0     0 ?        I    17:23   0:00 [kworker/u2:1-loop0]
 root          89  2.0  0.0      0     0 ?        I    17:23   0:01 [kworker/u2:2-events_unbound]
 root          90  0.2  0.0      0     0 ?        I<   17:23   0:00 [kworker/0:1H-kblockd]
 root          91  0.0  0.0      0     0 ?        S    17:23   0:00 [kswapd0]
 root          92  0.0  0.0      0     0 ?        S    17:23   0:00 [ecryptfs-kthrea]
 root          94  0.0  0.0      0     0 ?        I<   17:23   0:00 [kthrotld]
 root          95  0.0  0.0      0     0 ?        I<   17:23   0:00 [acpi_thermal_pm]
 root          96  0.0  0.0      0     0 ?        I<   17:23   0:00 [nvme-wq]
 root          97  0.0  0.0      0     0 ?        I<   17:23   0:00 [nvme-reset-wq]
 root          98  0.0  0.0      0     0 ?        I<   17:23   0:00 [nvme-delete-wq]
 root          99  0.0  0.0      0     0 ?        S    17:23   0:00 [scsi_eh_0]
 root         100  0.0  0.0      0     0 ?        I<   17:23   0:00 [scsi_tmf_0]
 root         101  0.0  0.0      0     0 ?        S    17:23   0:00 [scsi_eh_1]
 root         102  0.0  0.0      0     0 ?        I<   17:23   0:00 [scsi_tmf_1]
 root         103  0.0  0.0      0     0 ?        I<   17:23   0:00 [vfio-irqfd-clea]
 root         104  0.0  0.0      0     0 ?        I<   17:23   0:00 [kvub300c]
 root         105  0.0  0.0      0     0 ?        I<   17:23   0:00 [kvub300p]
 root         106  0.0  0.0      0     0 ?        I<   17:23   0:00 [kvub300d]
 root         107  0.0  0.0      0     0 ?        I<   17:23   0:00 [mld]
 root         108  0.0  0.0      0     0 ?        I<   17:23   0:00 [ipv6_addrconf]
 root         109  0.0  0.0      0     0 ?        I    17:23   0:00 [kworker/u2:3]
 root         118  0.0  0.0      0     0 ?        I<   17:23   0:00 [kstrp]
 root         119  0.0  0.0      0     0 ?        I<   17:23   0:00 [zswap-shrink]
 root         120  0.0  0.0      0     0 ?        I<   17:23   0:00 [kworker/u3:0]
 root         125  0.0  0.0      0     0 ?        I<   17:23   0:00 [charger_manager]
 root         950  0.4  0.2  14384  4584 ?        Ss   17:23   0:00 udevd --daemon --resolve-names=early
 message+    2449  0.0  0.1   8276  3464 ?        Ss   17:23   0:00 dbus-daemon --system
 root        2469  0.0  0.0   3856   152 ?        Ss   17:23   0:00 syslogd -m 0
 root        2472  0.0  0.0   3800  1872 ?        Ss   17:23   0:00 klogd
 root        2680  0.1  0.2   8304  4892 tty1     Ss+  17:23   0:00 -sh
 root        2681  0.0  0.0   2816  1948 tty2     Ss+  17:23   0:00 getty 38400 tty2
 root        2710  0.1  0.2  10572  5024 ?        S    17:23   0:00 /usr/sbin/bluetoothd
 root        2740  0.0  0.2  16780  4328 ?        Ss   17:23   0:00 /usr/sbin/connmand --nodnsproxy
 root        2748  0.2  0.3  16520  6604 ?        S    17:23   0:00 /sbin/wpa_supplicant -u -s -O /run/wpa_supplicant
 root        2777  0.0  0.1   7588  4004 tty1     S+   17:23   0:00 /bin/sh /bin/xwin
 root        2789  0.0  0.1   7384  3504 tty1     S+   17:23   0:00 /bin/sh /bin/startxwayland /root/.xinitrc
 root        2856  0.0  0.0   2828  1040 ?        S    17:23   0:00 bpfilter_umh
 root        2924 14.1  4.5 193012 92704 tty1     Sl+  17:23   0:05 dwl-kiosk -s Xwayland :0 -auth /root/.Xauthority  -dpi 96
 root        3020  0.1  0.2  26060  5200 ?        Sl   17:23   0:00 pup-volume-monitor
 daemon      3048  0.0  0.0   6252   348 ?        Ss   17:23   0:00 /usr/sbin/nscd
 root        3066  2.8  4.5 194444 91816 tty1     S+   17:23   0:00 Xwayland :0 -auth /root/.Xauthority -dpi 96
 root        3132  0.0  0.0   6456  1644 tty1     S+   17:23   0:00 swayidle
 root        3133  2.5  1.1  41080 23784 tty1     S+   17:23   0:00 jwm
 root        3154  0.0  0.1   8292  2056 tty1     S+   17:23   0:00 dbus-launch --exit-with-x11 --sh-syntax
 root        3155  0.0  0.1   8052  3232 ?        Ss   17:23   0:00 /usr/bin/dbus-daemon --syslog --fork --print-pid 5 --print-address 7 --session
 spot        3163  0.0  0.0   8292  2020 tty1     S+   17:23   0:00 dbus-launch --exit-with-x11
 spot        3164  0.0  0.1   8072  3196 ?        Ss   17:23   0:00 /usr/bin/dbus-daemon --syslog --fork --print-pid 5 --print-address 7 --session
 spot        3173  0.8  0.7 384856 15064 ?        Sl   17:23   0:00 pulseaudio --start --log-target=syslog
 root        3182  0.0  0.2  25824  5824 ?        Sl   17:23   0:00 /usr/libexec/dconf-service
 spot        3206  0.0  0.2  25824  5716 ?        Sl   17:23   0:00 /usr/libexec/dconf-service
 root        3353  0.1  0.2   9152  4724 ?        Ss   17:23   0:00 xload -nolabel -fg #56718A -hl white -bg #ccc
 spot        3360  7.1  2.3 111668 46684 ?        Sl   17:23   0:01 /usr/bin/python3 /usr/bin/blueman-applet.bin
 spot        3367  0.8  3.7 219836 76060 ?        Sl   17:23   0:00 /usr/bin/connman-ui-gtk.bin
 root        3375  0.0  0.0   2828  1136 ?        S    17:23   0:00 fixmenusd fixmenus; jwm -reload; killall -HUP labwc
 root        3386  2.0  3.8 229392 78540 ?        Sl   17:23   0:00 pcmanfm --desktop
 root        3397  0.5  3.6 219076 73520 ?        Sl   17:23   0:00 firewallstatus
 root        3400  0.6  3.6 219136 73224 ?        S    17:23   0:00 freememapplet_tray
 spot        3409  0.6  3.7 484824 76564 ?        S    17:23   0:00 /usr/bin/pa-applet.bin
 root        3431  0.3  0.0   3856   156 ?        Ss   17:23   0:00 acpid
 root        3961  4.2  1.8  81680 36472 ?        Sl   17:24   0:00 /usr/bin/python3 /usr/libexec/blueman-mechanism
 root        3966  0.1  0.3  38320  7736 ?        Sl   17:24   0:00 /usr/libexec/polkitd --no-debug
 spot        3971  0.3  0.3  18200  7224 ?        S    17:24   0:00 /usr/lib/bluetooth/obexd
 spot        3973  2.1  2.1 110524 42624 ?        Sl   17:24   0:00 /usr/bin/python3 /usr/bin/blueman-tray

This is very clean and very good, considering the compatibility with legacy Puppy stuff that uses X11 tools like setxkbmap, the ability to run Wayland and X11 applications side-by-side, the functionality to RAM/CPU consumption ratio, and how snappy it feels. The Wayland port of Puppy is starting to look like a bright future for Puppy, and a leap forward.