Linuxの起動が遅い原因の調査方法(その2)

Linuxの起動がものすごく遅い.5分ぐらい掛かる.原因を調査,解決したので手順をまとめておきます.

起動時のログを見る方法

systemdにはシステム起動時のログを分析する機能があります.使い方も簡単

まずは systemd-analyze を実行します

$ systemd-analyze 
Startup finished in 16.337s (firmware) + 2.699s (loader) + 2.958s (kernel) + 5min 1.771s (userspace) = 5min 23.767s 
graphical.target reached after 5min 1.764s in userspace

起動には5分23秒かかっていて,そのうち userspace の処理で 5分1秒も掛かっていることが解ります.たしかに遅い.

より詳細なログを見ます.systemd-analyze に blame オプションを付けます.

$ systemd-analyze  blame

以下のような表示がでました.

5min 400ms ifupdown-wait-online.service
   12.723s ifupdown-pre.service
   10.659s dev-sdc3.device
    5.322s NetworkManager-wait-online.service
    4.624s networking.service
    2.605s udisks2.service
    2.523s smartmontools.service
    1.533s man-db.service
    1.108s vmware.service
     629ms logrotate.service
     480ms apt-daily-upgrade.service
     474ms apt-daily.service
     243ms upower.service
     200ms systemd-journal-flush.service
     156ms vmware-USBArbitrator.service
     120ms exim4.service
      98ms user@1000.service
      92ms nmbd.service
      82ms accounts-daemon.service
      71ms systemd-udev-trigger.service
      65ms avahi-daemon.service
      64ms smbd.service
      62ms fancontrol.service
      60ms NetworkManager.service
      58ms polkit.service
      54ms winbind.service
      53ms systemd-logind.service
      53ms apache2.service
      52ms systemd-journald.service
      49ms rtkit-daemon.service
      49ms systemd-sysusers.service
      47ms nvidia-persistenced.service
      45ms keyboard-setup.service
      45ms home.mount
      44ms wpa_supplicant.service
      43ms dictd.service
      42ms phpsessionclean.service
      39ms systemd-udevd.service
      38ms ModemManager.service
      36ms etc-setserial.service
      34ms lm-sensors.service
      34ms exim4-base.service
      33ms setserial.service
      33ms rng-tools-debian.service
       以下省略

問題があるのは先頭の1行

5min 400ms ifupdown-wait-online.service

この部分です. ifupdown-wait-online.service が猛烈に遅いようです.

サービスの詳細を調べる方法

ifupdown-wait-online.service とは一体何者でしょうか? 調べてみます

最初にサービスの稼働状況を確認します

$ systemctl status ifupdown-wait-online.service

結果

● ifupdown-wait-online.service - Wait for network to be configured by ifupdown
     Loaded: loaded (/lib/systemd/system/ifupdown-wait-online.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Sat 2021-07-31 16:27:14 JST; 24h ago
    Process: 332 ExecStart=/lib/ifupdown/wait-online.sh (code=exited, status=1/FAILURE)
   Main PID: 332 (code=exited, status=1/FAILURE)
        CPU: 372ms

サービスはエラーで停止しています

サービスの定義ファイル /lib/systemd/system/ifupdown-wait-online.service の中身を眺めてみます

cat /lib/systemd/system/ifupdown-wait-online.service
[Unit]
Description=Wait for network to be configured by ifupdown
DefaultDependencies=no
Before=network-online.target
ConditionFileIsExecutable=/sbin/ifup

[Service]
Type=oneshot
ExecStart=/lib/ifupdown/wait-online.sh
RemainAfterExit=yes

[Install]
WantedBy=network-online.target

ExecStart=/lib/ifupdown/wait-online.sh ですから, 実体は /lib/ifupdown/wait-online.sh .拡張子的に sh のシェルスクリプトです

$ cat /lib/ifupdown/wait-online.sh

長いので,詳細は割愛.wait-online.shの冒頭は以下のように実装されています

#!/bin/sh
set -e

WAIT_ONLINE_METHOD="ifup"
WAIT_ONLINE_IFACE=""
WAIT_ONLINE_ADDRESS=""
WAIT_ONLINE_TIMEOUT=300

[ -f /etc/default/networking ] && . /etc/default/networking

9行目で,設定ファイルは /etc/default/networking であることがわかります.
(4行目から7行目で,デフォルト値を設定./etc/default/networkingの内容で適宜値を変更する実装になっています)

/lib/ifupdown/wait-online.sh のデバッグ

デバッグするために,とりあえず -x オプションを指定してスクリプトを実行してみます

$ sudo /bin/sh -x /lib/ifupdown/wait-online.sh

結論だけ言うと,以下のコマンドで処理が止まっていました.

$ /sbin/ifquery --state eth1

原因

  1. /lib/ifupdown/wait-online.sh はネットワークインタフェースが利用可能になるまで wait するサービス
  2. このマシンでは eth0 と eth1 の2つのネットワークインタフェースが存在した
  3. しかし eth1 は使用していなかった(実験用の予備で普段はLANケーブルを外している)
  4. /lib/ifupdown/wait-online.sh は eth1がupするまで wait処理をおこない,時間切れで TIMEDOUTエラーで異常終了していた

ということでした

対処

eth1 の wait処理は不要なので /etc/default/networkingを編集して eth1は無視するように設定を変更しました.

WAIT_ONLINE_IFACE="eth0"

まとめ

  • 起動時のログは systemd-analyze で確認できる
  • 詳細なログは systemd-analyze blame で確認できる
  • 問題があるスクリプトが特定できたら,"-x"オプションを使ってデバッグする

関連するエントリ

同様の手順で別トラブルを解決したエントリもあります.併せてご覧ください!
pyopyopyo.hatenablog.com

debian/changelog からバージョン番号を取り出す方法

debianのソースパッケージから,生成されるバイナリパッケージのバージョン情報を抽出するには dpkg-parsechangelog を使うのが簡単.

dpkg-parsechangelog  --file path/to/changelog  --show-field Version 
dpkg-parsechangelog  --file path/to/changelog  --show-field Source 

"--show-field"で,抽出したい情報のフィールド名を指定する

フィールド名とdebian/changelogの書式の対応は以下の通り

Source (Version) Distribution; Urgency

-- Maintainer (Date)

あと Changelogunix timestamp を取る場合は

dpkg-parsechangelog  --file path/to/changelog  --show-field Timestamp 

とすれば良い.

さすがデビアン.よくできている.