zero-byte svg file generated when systemd-bootchart invoked using "init" kernel parameter

[jamuir]

According to man systemd-bootchart, the recommended way of running systemd-bootchart is using the init kernel parameter (which you can set from the grub menu):

init=/usr/lib/systemd/systemd-bootchart

Unfortunately, this seems to have stopped working.

On Fedora 41, with systemd v256, the generated svg file is zero bytes:

Fedora Linux 41 (Server Edition)
Kernel 6.11.4-301.fc41.aarch64 on an aarch64 (tty1)
vbox login: jmuir
Password:
Last login: Tue Jan 14 14:16:28 on tty1
jmuir@vbox:~$ ls -1 /run/log
total 0
rw-rw-rw-.  1 root root             0 Jan 14 14:22 bootchart-20250114-1422.svg
drwxr-sr-x+ 2 root systemd-journal 40 Jan 14 14:22 journal

Here is my kernel command-line:

jmuir@vbox:~$ xargs -n1 < /proc/cmdline
BOOT_IMAGE=(hdB,gpt2)/vmlinuz-6.11.4-301.fc41.aarch64
root=/dev/mapper/fedora_vbox-root
ro
rd.lum.lu=fedora_vbox/root
rhgb
init=/usr/1ib/systemd/systemd-bootchart

systemd-bootchart should run for about 3 mins (1800 samples at 10 samples/sec):

jmuir@vbox:~$ cat /etc/systemd/bootchart.conf
# This file is part of systemd.
#
# systemd is free software; you can redistribute it and/or modify it
# under the terms of the GNU Lesser General Public License as published by
# the Free Software Foundation; either version 2.1 of the License, or
# (at your option) any later version.
#
# Entries in this file show the compile time defaults.
# You can change settings by editing this file.
# Defaults can be restored by simply deleting this file.
# See bootchart.conf (5) for details.

[Bootchart]
Samples=1800
Frequency=10
#Relative=no
#Filter=yes
#Output=<folder name, defaults to /run/log>
#Init=/path/to/init-binary
#PlotMemoryUsage=no
#PlotEntropyGraph=no
#ScaleX=100
#ScaleY=20
#ControlGroup=no
#PerCPU=no

Version information:

jmuir@vbox:~$ systemctl --version
systemd 256 (256.7-1.fc41)
+PAM *AUDIT +SELINUX -APPARMOR *IMA SMACK *SECCOMP -GCRYPT *GNUTS OPENSSL *ACL *BLKID +CURL *ELFUTILS +FIDO2 +IDN -IDN -IPTC +KMOD *LIBCRYPTSETUP *LIBCRYPTS
ETUP_PLUGINS +LIBFDISK +PCREZ +PWQUALITY +P11KIT +QRENCODE +TPM +BZIP2 +LZA +XZ *ZLIB *ZSTD +BPF_FRAMEWORK *XKBCOMMON UTMP *SYSUINIT *LIBARCHIVE

jmuir@vbox:~$ strings /usr/lib/systemd/systemd-bootchart | grep systemd-bootchart
{"type" : "rpm", "name": "systend-bootchart"
systemd-bootchart wrote %s
systemd-bootchart: sample time overrun %i times
systemd-bootchart-235-1.fc41.aarch64 .debug

[jamuir]

I was able to capture an strace log using the following debug init program:

// init-jm.c
#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>

#define BOOTCHART "/usr/lib/systemd/systemd-bootchart"
#define SYSTEMD   "/usr/lib/systemd/systemd"
#define STRACE    "/usr/bin/strace"

int main() {
  pid_t fpid;
  pid_t mypid;
  int fd = -1;
  fd = open("/dev/kmsg", O_WRONLY);

  mypid = getpid();

  dprintf(fd, "begin init-jm, mypid=%d\n", mypid);

  fpid = fork();
  if (fpid < 0) {
    perror("call to fork() failed");
  } else if (fpid == 0) {
    mypid = getpid();
    dprintf(fd, "this is the child, mypid=%d\n", mypid);
    execl(STRACE, "@strace", "-o", "/run/log/strace.log", BOOTCHART, NULL);
  } else {
    mypid = getpid();
    dprintf(fd, "this is the parent, mypid=%d\n", mypid);
    execl(SYSTEMD, SYSTEMD, NULL);
  }

  dprintf(fd, "end init-jm, mypid=%d\n", mypid);

  return 0;
}

Here is the kernel command-line I used (note that I am running in permissive mode) and the resulting contents of /run/log:

jmuir@vbox:~$ xargs -n1 < /proc/cmdline 
BOOT_IMAGE=(hd0,gpt2)/vmlinuz-6.11.4-301.fc41.aarch64
root=/dev/mapper/fedora_vbox-root
ro
rd.lvm.lv=fedora_vbox/root
rhgb
enforcing=0
init=/usr/lib/systemd/init-jm

jmuir@vbox:~$ ls -l /run/log
total 96
-rw-rw-rw-. 1 root root                0 Jan 14 16:00 bootchart-20250114-1600.svg
drwxr-sr-x+ 2 root systemd-journal    40 Jan 14 16:00 journal
-rw-rw-rw-. 1 root root            97423 Jan 14 16:00 strace.log

The strace log shows that systemd-bootchart is sent SIGHUP just after it starts executing.

...
pread64(166, "systemd-bootcha (512, #threads: "..., 4095, 0) = 4095
getdents64(5, 0xaaaad4d34640 /* 0 entries */, 32768) = 0
close(7)                                = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=83836333}, NULL) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=1, si_uid=0} ---
--- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1, si_uid=0} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
close(9)                                = 0
close(8)                                = 0
close(11)                               = 0
close(10)                               = 0
close(13)                               = 0
...

in src/bootchart.c you can see that systemd-bootchart catches SIGHUP and then set a global variable to exit its main loop nicely.

Full strace log is attached.
strace-init-jm.log

[jamuir]

@bluca , the root cause here is that PID 1 is sending SIGHUP to systemd-bootchart shortly after it starts up.

could this be a systemd defect?

maybe the issue should be moved/linked there.

[sofar]

Maybe not a bug, although if pid == 1 we can certainly ignore SIGHUP and a few other signals...