Systemd-analyze blame producing "garbage" output

General system Applications
1

just into some research about an issue around systemd and see that systemd-analyze blame now showing up like this:
2022-11-24_12-57

And it should look like so:
2022-11-24_12-56

I try running in bash and zsh it shows the same i do not see it on XFCE4 VM not set to German locales…

OS could be related… but it is the same on a fresh install of GNOME set to de…

Not related to locales i think just set GNOME to en_US and got the same…

it seems to be around the number of numbers in the front?
2022-11-24_13-07
you see it does scramble the format with 1.074s but work with 452ms …

2

Mine looks “normal” (Arch on GNOME)

[pebcak@arch-gnome ~]$ systemd-analyze blame 
475ms dev-nvme0n1p2.device
437ms upower.service
388ms ufw.service
331ms accounts-daemon.service
208ms ldconfig.service
202ms bolt.service
201ms systemd-remount-fs.service
199ms iwd.service
135ms user@1000.service
121ms systemd-udev-trigger.service
121ms systemd-backlight@leds:dell::kbd_backlight.service
103ms systemd-logind.service
101ms apparmor.service
 97ms systemd-modules-load.service
 97ms libvirtd.service
 66ms systemd-journal-flush.service
 65ms systemd-timesyncd.service
 64ms systemd-journald.service
 63ms colord.service

:thinking:

3

yea you show only the part with 5 letters in front :wink:

4

and it could be systemd-boot causing it too ?
my xfce4 install on grub does not have the issue…

5

That’s what I get on a not-bloated system :stuck_out_tongue_winking_eye: :sweat_smile:

the whole output 
[pebcak@arch-gnome ~]$ systemd-analyze blame 
475ms dev-nvme0n1p2.device
437ms upower.service
388ms ufw.service
331ms accounts-daemon.service
208ms ldconfig.service
202ms bolt.service
201ms systemd-remount-fs.service
199ms iwd.service
135ms user@1000.service
121ms systemd-udev-trigger.service
121ms systemd-backlight@leds:dell::kbd_backlight.service
103ms systemd-logind.service
101ms apparmor.service
 97ms systemd-modules-load.service
 97ms libvirtd.service
 66ms systemd-journal-flush.service
 65ms systemd-timesyncd.service
 64ms systemd-journald.service
 63ms colord.service
 60ms Data-Backups.mount
 59ms Data-Library.mount
 59ms Data-Music.mount
 58ms Data-Photos.mount
 58ms Data-Videos.mount
 57ms bluetooth.service
 54ms Data-VirtualMachines.mount
 50ms efi.mount
 50ms systemd-tmpfiles-clean.service
 49ms swap.mount
 49ms home.mount
 48ms NetworkManager.service
 47ms var-cache.mount
 44ms systemd-fsck@dev-disk-by\x2duuid-BCD6\x2d459F.service
 40ms udisks2.service
 37ms var-lib-flatpak.mount
 36ms systemd-udevd.service
 36ms var-lib-libvirt.mount
 35ms systemd-tmpfiles-setup.service
 34ms var-log.mount
 33ms alsa-restore.service
 32ms boot.mount
 32ms cpupower.service
 31ms polkit.service
 30ms home-pebcak-.local-share-gnome\x2dboxes.mount
 29ms udisks2-zram-setup@zram0.service
 29ms home-pebcak-.mozilla.mount
 28ms home-pebcak-.var.mount
 27ms swap-swapfile.swap
 27ms systemd-machined.service
 27ms dev-zram0.swap
 26ms var-cache-pacman-pkg.mount
 24ms dbus.service
 24ms sys-kernel-config.mount
 21ms systemd-sysusers.service
 20ms sys-fs-fuse-connections.mount
 18ms systemd-journal-catalog-update.service
 17ms systemd-tmpfiles-setup-dev.service
 15ms dev-hugepages.mount
 14ms dev-mqueue.mount
 14ms gdm.service
 13ms sys-kernel-debug.mount
 13ms modprobe@fuse.service
 12ms systemd-zram-setup@zram0.service
 12ms sys-kernel-tracing.mount
 11ms kmod-static-nodes.service
 11ms modprobe@configfs.service
 10ms modprobe@drm.service
 10ms home-pebcak-.cache-mozilla.mount
 10ms user-runtime-dir@1000.service
 10ms dev-disk-by\x2duuid-204b749a\x2deb7e\x2d4b61\x2d850e\x2df7a82da8c988.swap
 10ms systemd-random-seed.service
 10ms tmp.mount
  9ms systemd-backlight@backlight:intel_backlight.service
  8ms systemd-user-sessions.service
  8ms systemd-update-utmp.service
  7ms systemd-sysctl.service
  7ms systemd-rfkill.service
  5ms systemd-update-done.service
  4ms rtkit-daemon.service

My output is from a system on BTRFS | systemd-boot | Archlinux | GNOME

6

is that first… on mine there are some stuff counting over a second one only these have the garbage formatting…
Just checked on KDE install systemd-boot and it was looking fine but after update it shows the garbage :wink:

I have only no clue on how to find what it is causing…

1 Like
7

Yes.

I have no access to my KDE and Cinnamon Arch test installs right now. I can take a look later this afternoon.

On this machine I have the following updates pending. They seem “hramless”, don’t they?

archlinux-keyring 20221110-1 -> 20221123-1
gtk3 1:3.24.34+r156+g812b3930d0-1 -> 1:3.24.35-1
mkinitcpio 32-2 -> 33-1
python-setuptools 1:65.5.1-1 -> 1:65.6.0-1
qt5-base 5.15.7+kde+r175-1 -> 5.15.7+kde+r176-1
sdl2 2.24.2-1 -> 2.26.0-1
veracrypt 1.25.9-3 -> 1.25.9-4

Seems an odd one. Let’s see if we get in more reports on this from other users.

8

Those aren’t scrambled or garbage. They are device units.

Perhaps you have something loading those devices at boot?

What happens if you remove the CD/ISO?

9

omg :wink: now when you saythis it looks legit i was looking at this in between doing other stuff… and my thought was that these x2did-wwn parts look like formatting code…

But i think on my install is something really screwed… as they all show way to long times…
2022-11-24_16-12
I do not see this on other installs… where it maxed on a bit over one second.
I have a lot of drives in the system but i do not have any ISO loaded here

10

That time is cumulative so the amount of time for all those device units is only a few milliseconds total.

11

so totally normal?
it shows over 230 lines with these device uuids i can somehow identify some of them as drives but i do not remember that they all was shown before like spamming the output.

And in addition other installs do not take that time to boot on this install it is over 7 minutes currently… same machine other install with almost the same stuff loaded on boot it is around 3 seconds…

12

I have the same long list of stuff. It’s all readable but i also don’t remember it being like this before. :thinking:

Edit: This is grub boot. Are you referring only to systemd-boot?

13

I also have a lot of drives and mine is the same.

It looks like it was a change in systemd v251.

3 Likes
14

This guy @dalto is very smart :wink:

15

mainly i wanted to fins out what exactly happens for something else… but sumble upon the output but it seems nothing related to systems-boot or grub… its this what you see in the report @dalto posted:

Unexpected behaviour you saw
systemd-analyze blame returns sys-module-configfs, sys-devices-platform-serial8250-tty-ttySXX.device, dev-ttySXX.device, and other devices including disks (returning duplicate entries for UUID, PARTUUID, PATH, etc).

its not a BUG its a feature:

2022-11-24_16-54
2022-11-24_16-54972×139 16.5 KB

16

Does this happen when one has several disks in the system or also in the systems with only one disk but with several partitions?

I’m not seeing this output on this install.

Name            : systemd
Version         : 252.2-1

$ systemd-analyze blame ## the first five lines
218ms user@1000.service
204ms dev-nvme0n1p4.device
123ms upower.service
117ms ufw.service
 95ms iwd.service
17

It is probably due to hardware differences.

Also, you are only sharing partial output so it is hard to see how it impacts you.

1 Like
18

On a fresh install inside a vm I do not got a single device output shown:

systemd-analyze blame 
[joe@joe-virtualbox ~]$ systemd-analyze blame
504ms dev-sda2.device
317ms firewalld.service
195ms lvm2-monitor.service
123ms systemd-sysusers.service
 90ms NetworkManager.service
 87ms user@1000.service
 81ms accounts-daemon.service
 80ms systemd-journal-flush.service
 74ms udisks2.service
 65ms ldconfig.service
 44ms systemd-udevd.service
 42ms upower.service
 39ms systemd-fsck@dev-disk-by\x2duuid-46B6\x2dFB81.service
 38ms avahi-daemon.service
 37ms systemd-udev-trigger.service
 36ms systemd-timesyncd.service
 35ms systemd-logind.service
 34ms dbus.service
 31ms systemd-tmpfiles-setup-dev.service
 30ms systemd-random-seed.service
 24ms systemd-sysctl.service
 24ms polkit.service
 22ms systemd-hostnamed.service
 21ms systemd-tmpfiles-setup.service
 20ms systemd-journald.service
 18ms systemd-tmpfiles-clean.service
 18ms swapfile.swap
 18ms systemd-modules-load.service
 16ms modprobe@fuse.service
 15ms vboxservice.service
 12ms boot-efi.mount
  9ms lightdm.service
  9ms systemd-journal-catalog-update.service
  8ms user-runtime-dir@1000.service
  8ms sys-kernel-debug.mount
  8ms dev-hugepages.mount
  7ms sys-kernel-tracing.mount
  7ms rtkit-daemon.service
  7ms dev-mqueue.mount
  7ms kmod-static-nodes.service
  6ms modprobe@configfs.service
  6ms modprobe@drm.service
  5ms systemd-remount-fs.service
  4ms alsa-restore.service
  4ms sys-fs-fuse-connections.mount
  4ms systemd-update-utmp.service
  4ms systemd-user-sessions.service
  3ms systemd-update-done.service
  2ms sys-kernel-config.mount
  1ms tmp.mount

same on other installs… seems it is removed again ? :person_shrugging:

here on my grub/mkinitcpio install on SLIMSHADY64 carry 6 harddrives:

xfce4-build ➜ ~ » systemd-analyze blame 
14.078s updatedb.service
10.474s man-db.service
 1.536s arch-audit.service
 1.432s tlp.service
  642ms vmware-networks.service
  356ms firewalld.service
  247ms dev-nvme1n1p2.device
  201ms udisks2.service
  177ms cups.service
  156ms upower.service
  147ms libvirtd.service
  141ms systemd-journal-flush.service
  124ms user@1000.service
  119ms systemd-modules-load.service
   83ms NetworkManager-wait-online.service
   75ms NetworkManager.service
   64ms systemd-udevd.service
   62ms systemd-udev-trigger.service
   57ms avahi-daemon.service
   56ms bluetooth.service
   55ms boot-efi.mount
   54ms dbus.service
   53ms accounts-daemon.service
   53ms geoclue.service
   52ms systemd-logind.service
   51ms systemd-machined.service
   45ms systemd-tmpfiles-setup-dev.service
   44ms systemd-tmpfiles-clean.service
   31ms systemd-tmpfiles-setup.service
   31ms logrotate.service
   29ms systemd-journald.service
   28ms colord.service
   24ms alsa-restore.service
   20ms systemd-fsck@dev-disk-by\x2duuid-XXX.service
   18ms systemd-timesyncd.service
   17ms wpa_supplicant.service
   16ms lightdm.service
   15ms systemd-sysctl.service
   14ms systemd-random-seed.service
   14ms polkit.service
   11ms swapfile.swap
   11ms lm_sensors.service
    9ms modprobe@fuse.service
    6ms dev-hugepages.mount
    6ms dev-mqueue.mount
    6ms sys-kernel-debug.mount
    5ms sys-kernel-tracing.mount
    5ms sys-kernel-config.mount
    5ms kmod-static-nodes.service
    5ms modprobe@configfs.service
    4ms systemd-update-utmp.service
    4ms modprobe@drm.service
    4ms user-runtime-dir@1000.service
    4ms systemd-rfkill.service
    3ms systemd-user-sessions.service
    3ms systemd-remount-fs.service
    2ms rtkit-daemon.service
    2ms tmp.mount
    2ms proc-sys-fs-binfmt_misc.mount
    1ms sys-fs-fuse-connections.mount
20

There is nothing obvious in the changelog but 252.2 did hit the repos yesterday.

On an unrelated side note, I saw this while reading through the changelog:

Booting in EFI mixed mode (a 64-bit kernel over 32-bit UEFI firmware) is now supported by sd-boot.

1 Like
21

ha ha funny… seems archlinux was to fast on taking grub to do that for the ISO ?