systemd-analyze: что тормозит загрузку и что не так в юните

systemd записывает, когда какой юнит начал и закончил запуск. systemd-analyze читает эти времена и показывает их тремя способами: итог загрузки, список юнитов и цепочку зависимостей. Та же команда проверяет юнит-файл раньше, чем его прочитает systemd.

Без подкоманды — итог загрузки учебной машины:

student@ubuntu:~$ systemd-analyze
Startup finished in 2.902s (kernel) + 6.382s (userspace) = 9.285s
multi-user.target reached after 6.356s in userspace.

kernel — ядро и initramfs до запуска systemd, userspace — работа systemd до конца загрузки. Загрузчик systemd-boot на UEFI передаёт ещё firmware и loader, GRUB этих времён не передаёт. Вторая строка называет цель загрузки и момент, когда systemd её достиг.

Кто сколько запускался — blame

student@ubuntu:~$ systemd-analyze blame | head -6
2.368s apparmor.service
2.208s labs-ssh-hostkeys.service
1.151s dev-vda4.device
 892ms containerd.service
 835ms rsyslog.service
 671ms ldconfig.service

Время в строке — сколько юнит запускался: от команды «запустить» до состояния active. Юниты стартуют параллельно, поэтому сумма времён больше всей загрузки, а первая строка списка могла никого не задержать. Кто держал загрузку, показывает critical-chain.

Время зависит от типа службы. У Type=oneshot в него входит вся работа ExecStart=. Служба Type=simple считается запущенной сразу, как systemd создал её процесс, — даже если программа потом минуту готовится принимать запросы.

В списке и службы, запущенные после загрузки. Тестовая служба с ExecStart=/bin/sleep 4 и Type=oneshot встала первой строкой:

4.007s lab-slow.service

Критическая цепочка

student@ubuntu:~$ systemd-analyze critical-chain
multi-user.target @6.356s
└─containerd.service @4.211s +892ms
  └─dbus.service @4.060s +131ms
    └─basic.target @4.045s
      └─sockets.target @4.044s
        └─lxd-installer.socket @4.030s +11ms
          └─sysinit.target @3.989s
            └─apparmor.service @1.618s +2.368s
              └─local-fs.target @1.603s

Две строки перед деревом объясняют значки: после @ — когда юнит стал активным (секунды от начала userspace), после + — сколько он запускался. Читай снизу вверх: каждый юнит ждал того, кто под ним. apparmor.service запускался 2.368 с, и sysinit.target дождался его только к 3.989 с — всё, что выше, стартовало после. Юниты, запущенные после того, как цель достигнута, в её цепочку не попадают.

Цепочка идёт по After=: из юнитов, после которых запускается этот, выбран тот, кто освободился последним. С именем юнита — чего ждал он сам; у первой строки только +:

student@ubuntu:~$ systemd-analyze critical-chain lab-slow.service
lab-slow.service +4.007s
└─nginx.service @4.114s +207ms
  └─basic.target @4.045s
    └─sockets.target @4.044s

lab-slow.service запускался 4 с, а до этого ждал nginx.service — у него After=nginx.service.

Проверка юнита — verify

systemd-analyze verify загружает юнит так же, как systemd при daemon-reload, и печатает, что ему не понравилось. Файл дают путём — его можно проверить ещё до копирования в /etc/systemd/system; установленный юнит — именем. Что печатает verify на ошибки в юните:

Код 0 значит только, что юнит загрузится. Строку с опечаткой и неверное значение systemd пропускает, и служба работает с умолчаниями: без After=, с типом simple. Чистый юнит — это пустой вывод.

• systemd — юниты, drop-in'ы и зависимости.
• systemctl — запуск, остановка и состояние служб.
• journalctl — журнал этой загрузки: journalctl -b.
• boot-grub — что происходит до systemd.
• systemd-hardening — systemd-analyze security.
• systemd-timers — systemd-analyze calendar.