cClaude.rocks ☕ Le blog

[Nouvelles technologies, sciences et coups de gueule…]

Menu
févr.
06
2023

Le temps nécessaire à une machine pour être opérationnel est une notion importante dans le confort d’utilisation d’une machine.

Voici un cas concret d’optimisation du démarrage lié au service logrotate.

Pour que l’article reste accessible, on se limitera à l’analyse du composant le plus lent pour le cas étudier (chez vous cela sera probablement un autre composant).

ඏ

Les commandes

Voici la liste des commandes qui vous seront utiles pour ce type d’analyse :

Le journal système

  • sudo journalctl -b ou sudo journalctl --boot qui permet de voir les logs liés au dernier démarrage. Notez que dans la documentation, on parle de « current boot ».

Comme toutes les commandes liées à systemd, journalctl accepte le paramètre --no-pager qui évite la pagination automatique.

Par défaut la pagination est active, c’est d’ailleurs indispensable depuis un terminal physique, mais moins utile dans un émulateur de terminal (depuis l’interface graphique) et contre-productif depuis un script.

sudo journalctl --no-pager --boot

Le résultat de cette commande peu paraître barbare, mais il est possible d’y trouver facilement quelques informations très utiles.

  • Les entrées sont horodatées, ce qui pour le sujet d’optimisation permet de voir à quoi la durée du démarrage est due.
  • La sortie utilise des couleurs, qui mettent en avant les parties plus ou moins souhaitables,
  • Vous remarquerez probablement quelques erreurs (lisez bien les messages cependant, car certaines peuvent être normales). Certaine erreurs peuvent être très faciles à traiter d’autres beaucoup moins, mais plus vous réduisez le nombre d’erreur au démarrage, plus il sera rapide.

L’analyseur de « systemd »

Pour aider à l’analyse du démarrage, la commande systemd-analyze sera votre ami…

Voici les différents usages de la commande systemd-analyze qui je vous propose d’utiliser pour optimiser le démarrage de vos machines.

systemd-analyze
systemd-analyze [--no-pager] critical-chain [--system] [--user]
systemd-analyze [--no-pager] blame [--system] [--user]
  • systemd-analyze – Vous donnera un résumé des temps de démarrages de la couche « système » ainsi que de la couche « utilisateur ».
  • systemd-analyze blame – Vous donnera le temps de démarrage de chacun des composants « système ».
  • systemd-analyze blame --system – Identique à * systemd-analyze blame.
  • systemd-analyze blame --user – Vous donnera le temps de démarrage de chacun des composants utilisateurs (Attention, on parle ici du « boot »).
systemd-analyze critical-chain
systemd-analyze critical-chain --system
systemd-analyze critical-chain --user
ඏ

Première analyse à l’aide de : « systemd-analyze »

systemd-analyze

Startup finished in 7.960s (kernel) + 1min 290ms (userspace) = 1min 8.251s
graphical.target reached after 1min 276ms in userspace

Presque 1 minute 30 pour accéder à l’interface graphique est clairement inacceptable.

ඏ

Analyse des éléments de la séquence de démarrage : « systemd-analyze --no-pager blame »

systemd-analyze --no-pager blame
  • Exemple de résultat 
    21.192s logrotate.service
19.485s networkd-dispatcher.service
17.924s udisks2.service
16.444s gpu-manager.service
13.973s systemd-journal-flush.service
13.698s accounts-daemon.service
13.093s NetworkManager-wait-online.service
12.277s dev-sda2.device
11.580s ModemManager.service
 8.951s polkit.service
 8.584s avahi-daemon.service
 8.578s NetworkManager.service
 7.782s thermald.service
 7.775s systemd-logind.service
 7.649s wpa_supplicant.service
 7.141s ubuntu-system-adjustments.service
 6.303s bluetooth.service
 6.102s xrdp.service
 4.744s systemd-udevd.service
 4.653s secureboot-db.service
 4.393s cups.service
 3.543s ssh.service
 3.267s networking.service
 3.249s xrdp-sesman.service
 2.628s grub-common.service
 2.302s alsa-restore.service
 2.029s apparmor.service
 2.004s systemd-resolved.service
 1.635s lm-sensors.service
 1.561s systemd-modules-load.service
 1.506s rsyslog.service
 1.458s systemd-tmpfiles-setup-dev.service
 1.400s lightdm.service
 1.393s keyboard-setup.service
 1.375s systemd-random-seed.service
 1.258s systemd-fsck@dev-disk-by\x2duuid-C591\x2d3A52.service
 1.178s grub-initrd-fallback.service
 1.124s systemd-sysusers.service
 1.115s systemd-tmpfiles-setup.service
 1.060s systemd-sysctl.service
 1.059s dns-clean.service
 1.055s openvpn.service
 1.036s e2scrub_reap.service
  957ms systemd-udev-trigger.service
  898ms colord.service
  883ms swapfile.swap
  688ms kerneloops.service
  518ms upower.service
  461ms systemd-backlight@backlight:intel_backlight.service
  433ms systemd-timesyncd.service
  423ms systemd-journald.service
  398ms user@1001.service
  394ms ifupdown-pre.service
  367ms systemd-rfkill.service
  319ms dev-hugepages.mount
  316ms dev-mqueue.mount
  314ms sys-kernel-debug.mount
  312ms sys-kernel-tracing.mount
  295ms modprobe@fuse.service
  292ms kmod-static-nodes.service
  292ms modprobe@configfs.service
  292ms modprobe@drm.service
  291ms lvm2-monitor.service
  274ms setvtrgb.service
  256ms systemd-update-utmp.service
  256ms blueman-mechanism.service
  214ms console-setup.service
  211ms user@1000.service
  210ms lsyncd.service
  210ms systemd-user-sessions.service
  180ms ufw.service
  151ms systemd-remount-fs.service
  127ms plymouth-read-write.service
  127ms finalrd.service
  120ms boot-efi.mount
   82ms rtkit-daemon.service
   54ms modprobe@chromeos_pstore.service
   19ms user-runtime-dir@1000.service
   18ms e2scrub_all.service
   15ms user-runtime-dir@1001.service
   15ms modprobe@efi_pstore.service
   12ms sys-fs-fuse-connections.mount
   12ms modprobe@pstore_blk.service
   10ms modprobe@pstore_zone.service
   10ms modprobe@ramoops.service
   10ms systemd-update-utmp-runlevel.service
    9ms sys-kernel-config.mount
    3ms plymouth-quit-wait.service
  242us blk-availability.service

Il ressort clairement que dans ce cas c’est logrotate.service qui le maillon faible puisqu’il nécessite plus de 21 secondes pour démarrer.

ඏ

Analyse de la séquence de démarrage : « systemd-analyze critical-chain »

Analyse de la séquence globale : « systemd-analyze critical-chain »

systemd-analyze critical-chain

The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @1min 276ms
└─multi-user.target @1min 275ms
  └─kerneloops.service @51.629s +688ms
    └─remote-fs.target @51.236s
      └─remote-fs-pre.target @51.235s

Analyse de la séquence pour un service donné : « systemd-analyze critical-chain NOM_DU_SERVICE »

On peut se limiter à l’analyse pour un service donné, par exemple :

systemd-analyze critical-chain kerneloops.service

systemd-analyze --user blame

Pour obtenir l’affichage à la couche « utilisateur », on utilisera :

systemd-analyze --user blame

4.127s evolution-source-registry.service
2.640s gvfs-goa-volume-monitor.service
2.295s pulseaudio.service
1.223s evolution-calendar-factory.service
 499ms gvfs-gphoto2-volume-monitor.service
 404ms evolution-addressbook-factory.service
 309ms obex.service
 118ms gvfs-afc-volume-monitor.service
 110ms gvfs-udisks2-volume-monitor.service
  75ms gvfs-metadata.service
  74ms gvfs-mtp-volume-monitor.service
  31ms dconf.service
  11ms gvfs-daemon.service
   8ms at-spi-dbus-bus.service
   5ms dbus.socket

systemd-analyze --system blame

Pour obtenir l’affichage à la couche « système », on utilisera :

systemd-analyze --system blame
  • Exemple de résultat 
    21.192s logrotate.service
19.485s networkd-dispatcher.service
17.924s udisks2.service
16.444s gpu-manager.service
13.973s systemd-journal-flush.service
13.698s accounts-daemon.service
13.093s NetworkManager-wait-online.service
12.277s dev-sda2.device
11.580s ModemManager.service
 8.951s polkit.service
 8.584s avahi-daemon.service
 8.578s NetworkManager.service
 7.782s thermald.service
 7.775s systemd-logind.service
 7.649s wpa_supplicant.service
 7.141s ubuntu-system-adjustments.service
 6.303s bluetooth.service
 6.102s xrdp.service
 4.744s systemd-udevd.service
 4.653s secureboot-db.service
 4.393s cups.service
 3.543s ssh.service
 3.267s networking.service
 3.249s xrdp-sesman.service
 2.628s grub-common.service
 2.302s alsa-restore.service
 2.029s apparmor.service
 2.004s systemd-resolved.service
 1.635s lm-sensors.service
 1.561s systemd-modules-load.service
 1.506s rsyslog.service
 1.458s systemd-tmpfiles-setup-dev.service
 1.400s lightdm.service
 1.393s keyboard-setup.service
 1.375s systemd-random-seed.service
 1.258s systemd-fsck@dev-disk-by\x2duuid-C591\x2d3A52.service
 1.178s grub-initrd-fallback.service
 1.124s systemd-sysusers.service
 1.115s systemd-tmpfiles-setup.service
 1.060s systemd-sysctl.service
 1.059s dns-clean.service
 1.055s openvpn.service
 1.036s e2scrub_reap.service
  999ms apt-daily-upgrade.service
  957ms systemd-udev-trigger.service
  898ms colord.service
  883ms swapfile.swap
  688ms kerneloops.service
  518ms upower.service
  461ms systemd-backlight@backlight:intel_backlight.service
  433ms systemd-timesyncd.service
  423ms systemd-journald.service
  398ms user@1001.service
  394ms ifupdown-pre.service
  367ms systemd-rfkill.service
  319ms dev-hugepages.mount
  316ms dev-mqueue.mount
  314ms sys-kernel-debug.mount
  312ms sys-kernel-tracing.mount
  295ms modprobe@fuse.service
  292ms kmod-static-nodes.service
  292ms modprobe@configfs.service
  292ms modprobe@drm.service
  291ms lvm2-monitor.service
  276ms update-notifier-download.service
  274ms setvtrgb.service
  256ms systemd-update-utmp.service
  256ms blueman-mechanism.service
  214ms console-setup.service
  210ms lsyncd.service
  210ms systemd-user-sessions.service
  180ms ufw.service
  151ms systemd-remount-fs.service
  127ms plymouth-read-write.service
  127ms finalrd.service
  120ms boot-efi.mount
   82ms rtkit-daemon.service
   54ms modprobe@chromeos_pstore.service
   18ms e2scrub_all.service
   15ms user-runtime-dir@1001.service
   15ms modprobe@efi_pstore.service
   12ms sys-fs-fuse-connections.mount
   12ms modprobe@pstore_blk.service
   10ms modprobe@pstore_zone.service
   10ms modprobe@ramoops.service
   10ms systemd-update-utmp-runlevel.service
    9ms sys-kernel-config.mount
    3ms plymouth-quit-wait.service
  242us blk-availability.service

Le service qui semble être le plus lent est dans ce cas logrotate.service, durant la séquence de démarrage c’est très probablement lié aux logs du démarrage.

Les logs du démarrage : « journalctl »

Si logrotate.service est lent c’est très certainement que les logs de journalctl sont lourds : Le billet 📰 Espace disque et journalctl traitait déjà de ce point.

On reprend donc ici ce qui était expliqué dans ce billet.

sudo journalctl --disk-usage # Attention ici sudo est indispensable pour connaître la taille de l’ensemble des logs.

Archived and active journals take up 1.0G in the file system.
  • Suite de la procédure spécifique à « journalctl »

    Voir le billet 📰 Espace disque et journalctl pour les explications.

    sudo mkdir -vp /etc/systemd/journald.conf.d/ &&
cat <<EOF | sudo tee /etc/systemd/journald.conf.d/system-max-use.conf
[Journal]
SystemMaxUse=50M

EOF

    sudo systemctl restart systemd-journald
sudo journalctl --verify
journalctl --disk-usage

    PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/user-1000.journal
PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/user-1001@36b314ea67614eaca0567f91e34381cb-0000000000097efd-0005f380498587db.journal
PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/user-1001.journal
PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/user-1000@9b181604e09c42bf9c586d64836828b8-0000000000098d96-0005f38b49793488.journal
PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/system.journal
PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/user-1001@3c0b59610c9c45ad97b382bfbe6ddec3-000000000009a63e-0005f3a83ef295f1.journal
PASS: /var/log/journal/dafd9a61376b4676aa8b190bc1ed4b43/system@07b7bb7210ec4c4cb16ef7b8ec4b72b7-000000000009a58a-0005f3a83c96a525.journal
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal' can see all messages.
      Pass -q to turn off this notice.
Archived and active journals take up 24.0M in the file system.

Redémarrage de la machine…

Une fois qu’on a pensé avoir optimisé quelque chose, un redémarrage de la machine s’impose pour voir ce qui a effectivement été gagné.

On relance alors « systemd-analyze »

systemd-analyze

Startup finished in 7.842s (kernel) + 43.642s (userspace) = 51.485s
graphical.target reached after 43.632s in userspace

Ici on contacte que le changement a été efficace.

En utilisant la commande blame on va pouvoir recommencer le processus.

systemd-analyze --system blame

14.172s gpu-manager.service
14.020s networkd-dispatcher.service
13.762s accounts-daemon.service
12.062s udisks2.service
…
ඏ

Liens

ᦿ

ℹ 2006 - 2024 | 🏠 Accueil du domaine | 🏡 Accueil du blog