cClaude.rocks ☕ Le blog

[Nouvelles technologies du libre, sciences et coups de gueule…]

Menu

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