Tech Notes

Article

systemd の起動遅延を追跡し、NetworkManager-wait-online と不要な bridge を整理してブート時間を短縮した記録

2 min read

systemd-analyze と NetworkManager の状態確認を使い、起動遅延の原因を特定して不要な bridge 設定を削除するまでの検証記録です。snap の見え方、wait-online の意味、Docker を要件として残した判断まで含めてまとめます。

linuxsystemdnetworkmanagerdockerbootUbuntu

はじめに

Linux の起動が妙に遅いとき、見た目が派手な snap や大量の loop デバイスに目を奪われがちです。 しかし今回の検証では、実際の主犯は NetworkManager-wait-online に引っ張られていた不要な bridge 設定 でした。

本記事では、実際に手を動かして確認した順序を重視しながら、以下を記録します。

  • 何を見て遅延を疑ったか
  • どのコマンドで切り分けたか
  • どこで判断を誤りやすいか
  • 最終的に何を削除し、どう改善したか
  • なお残った Docker 起動時間をどう扱うべきか

なお、このセッションでは記事に同梱できる画像添付は確認できなかったため、images/ ディレクトリは空で作成しています。

検証環境

会話内で確認できた範囲の情報を整理すると、環境はおおむね以下です。

  • Linux デスクトップ環境
  • systemd 採用ディストリビューション
  • NetworkManager を利用
  • Docker を常用
  • Docker コンテナ上で Samba を動かし、家庭内 NAS を兼用
  • libvirt 関連の socket も存在
  • snapd が導入済み
  • ホスト名やユーザー名など、公開不要な識別子は伏せています

目的

今回の目的は、単に systemd-analyze の数字を眺めることではありません。 実害のある起動遅延を減らしつつ、要件として必要なサービスは残す ことが目的です。

特に今回の前提として、Docker は開発用の任意サービスではなく、Samba コンテナ経由で NAS として利用しているため、単純に停止・無効化して終わり、という方針は採りませんでした。

最初に見えていた症状

起動遅延の調査中、systemd-analyze では snap 関連の unit が多数見えていました。

text
997ms snapd.seeded.service
684ms dev-loop10.device
681ms dev-loop9.device
677ms dev-loop8.device
...
418ms snap-aws\x2dcli-1997.mount
418ms snap-aws\x2dcli-2011.mount
417ms snap-lxd-36554.mount
417ms snap-bare-5.mount
416ms snap-mesa\x2d2404-1165.mount
416ms snap-lxd-32662.mount

この時点では「snap が大量に mount されているのが遅いのではないか」と疑っていました。

snap 関連の mount が大量に見える理由

まず整理しておくべきなのは、snap の実装です。

snap は通常の展開済みディレクトリではなく、squashfs イメージを loop デバイスとしてマウントして使う 方式です。 そのため dev-loop*.device と snap-*.mount が大量に見えるのは、実装上ある意味で正常です。

また、同じアプリの revision が複数見えることがあります。 これは snap がロールバックや更新時の切り戻しに備えて複数 revision を保持するためです。

ここで大事なのは次の点です。

  • systemd-analyze blame は「その unit にどれだけ時間がかかったか」を見せる
  • しかし、それが 起動全体の律速 とは限らない

このため、次は critical-chain を確認する方針に切り替えました。

critical-chain で見えた本当の遅延

最初に確認できた systemd-analyze critical-chain は次のとおりでした。

text
graphical.target @1min 23.300s
└─multi-user.target @1min 23.300s
  └─docker.service @1min 5.387s +17.913s
    └─network-online.target @1min 5.364s
      └─network.target @5.288s
        └─NetworkManager.service @4.152s +1.135s
          └─dbus.service @4.050s +94ms
            └─basic.target @4.045s
              └─sockets.target @4.045s
                └─libvirtd-ro.socket @4.045s
                  └─libvirtd.socket @4.025s +19ms
                    └─sysinit.target @3.977s
                      └─systemd-resolved.service @3.824s +149ms
                        └─systemd-tmpfiles-setup.service @3.745s +69ms
                          └─local-fs.target @3.713s
                            └─run-docker-netns-51642212a849.mount @1min 23.004s
                              └─local-fs-pre.target @718ms
                                └─multipathd.service @655ms +61ms
                                  └─systemd-remount-fs.service @553ms +68ms
                                    └─systemd-journald.socket @454ms
                                      └─-.mount @417ms
                                        └─-.slice @417ms

この時点で重要なのは以下の 2 点です。

  1. network.target までは 5 秒程度で到達している
  2. しかし network-online.target までが 約 60 秒遅い

つまり、基礎的なネットワーク起動そのものではなく、 「ネットワークが online になったと systemd が判断するまでの待機」 が問題だと見えてきました。

その後ろに docker.service が約 18 秒かかっていますが、まずは network-online.target の遅延理由を潰すべきと判断しました。

NetworkManager-wait-online の意味

NetworkManager-wait-online.service は、NetworkManager が「起動完了」と判断するまで network-online.target の到達を遅らせる oneshot サービスです。 remote mount やネットワーク前提のサービスを起動順序上で守るためには意味があります。

一方で、NetworkManager 側に「アクティベーション中のプロファイル」が残り続けると、そのぶん待機も伸びます。 このため、wait-online 自体を責める前に、NetworkManager が何を待っているのかを見る 必要があります。

まず取得したログと状態

最初に確認したのは以下です。

bash
journalctl -b -u NetworkManager-wait-online.service
nmcli device status

得られた結果は次のとおりです。

NetworkManager-wait-online のログ

text
3月 11 19:18:29 <host> systemd[1]: Starting NetworkManager-wait-online.service - Network Manager Wait Online...
3月 11 19:19:29 <host> systemd[1]: NetworkManager-wait-online.service: Main process exited, code=exited, status=1/FAILURE
3月 11 19:19:29 <host> systemd[1]: NetworkManager-wait-online.service: Failed with result 'exit-code'.
3月 11 19:19:29 <host> systemd[1]: Failed to start NetworkManager-wait-online.service - Network Manager Wait Online.

nmcli device status

text
DEVICE           TYPE      STATE                     CONNECTION
eno1             ethernet  接続済み                  netplan-eno1
br0              bridge    接続中 (IP 設定を取得中)  br0
br-8d11c8e85c79  bridge    接続済み (外部)           br-8d11c8e85c79
docker0          bridge    接続済み (外部)           docker0
lo               loopback  接続済み (外部)           lo
br-0797dd4547d2  bridge    接続済み (外部)           br-0797dd4547d2
br-3a84d1958d3d  bridge    接続済み (外部)           br-3a84d1958d3d
br-e2dfad8cd55c  bridge    接続済み (外部)           br-e2dfad8cd55c
virbr0           bridge    接続済み (外部)           virbr0
veth41c10ac      ethernet  管理無し                  --
veth923e801      ethernet  管理無し                  --

この時点で、eno1 はすでに接続済みなのに、br0 が 「接続中 (IP 設定を取得中)」 のまま止まっていることが見えました。 つまり、wait-online が真面目に待っていた相手は br0 です。

原因の仮説

この時点での仮説は明確です。

  • eno1 は通常の Ethernet 接続としてすでに使われている
  • 一方で br0 も online 化しようとしている
  • しかし bridge 側の構成が不要または破綻していて、IP 設定取得中のまま完了できない
  • 結果として NetworkManager-wait-online.service が timeout まで待たされている

要するに、wait-online が遅いのではなく、NetworkManager の接続プロファイル設計が壊れていた という判断です。

解決策として採った方針

この時点での選択肢は 2 つでした。

  1. br0 が本当に必要なら、bridge 配下に物理 NIC を正しくぶら下げる構成に修正する
  2. br0 が不要なら、削除する

今回は実運用上 br0 が不要だったため削除したところ、起動時間が大きく改善しました。

改善後の critical-chain

改善後の systemd-analyze critical-chain は次のとおりです。

text
graphical.target @27.943s
└─multi-user.target @27.943s
  └─docker.service @10.302s +17.640s
    └─network-online.target @10.282s
      └─NetworkManager-wait-online.service @5.201s +5.080s
        └─NetworkManager.service @4.157s +1.034s
          └─dbus.service @4.044s +64ms
            └─basic.target @4.026s
              └─sockets.target @4.025s
                └─libvirtd-ro.socket @4.024s
                  └─libvirtd.socket @3.995s +22ms
                    └─sysinit.target @3.950s
                      └─systemd-resolved.service @3.800s +147ms
                        └─systemd-tmpfiles-setup.service @3.719s +50ms
                          └─local-fs.target @2.284s
                            └─run-user-1000-gvfs.mount @28.579s
                              └─run-user-1000.mount @25.358s
                                └─local-fs-pre.target @684ms
                                  └─multipathd.service @620ms +61ms
                                    └─systemd-remount-fs.service @539ms +54ms
                                      └─systemd-journald.socket @451ms
                                        └─system.slice @427ms
                                          └─-.slice @427ms

改善前後を比較すると、次が明確に言えます。

  • graphical.target 到達は 約 1 分 23 秒 → 約 28 秒
  • NetworkManager-wait-online.service は 約 60 秒級の失敗待ち → 約 5 秒
  • ボトルネックの中心は br0 だった

Docker についての判断

改善後に残った大きな時間は docker.service の約 17.6 秒でしたが、Samba コンテナを動かし、家庭内 NAS の役割を担っているため、起動必須のサービスです。 そのため、今回のブート改善では Docker は除外対象としました。

今回の検証で得られた知見

1. snap が派手でも、主犯とは限らない

dev-loop*.device や snap-*.mount は見た目がうるさいですが、それだけで本丸とは限りません。 まずは critical-chain を見て、本当に起動全体の律速かを確認するべきです。

2. network.target と network-online.target は別物

network.target まで早く到達していても、network-online.target で長く待つことがあります。 この差を見ないと、ネットワーク周りの調査を見誤ります。

3. wait-online が悪いのではなく、待たせている profile が悪いことがある

今回の本質はここです。 NetworkManager-wait-online.service は壊れていません。 むしろ、壊れた構成をきちんと待った結果、遅延が表面化しました。

4. bridge 設定の残骸は boot をかなり汚す

過去に作った br0 が不要になっていても、autoconnect 設定が残っているだけで boot の大きな遅延要因になります。 Docker や libvirt を触る環境では特に起こりやすいです。

実施した調査コマンド一覧

今回の会話で実際に使った、または確認対象として挙げたコマンドを整理しておきます。

起動遅延の全体像確認

bash
systemd-analyze blame
systemd-analyze critical-chain

wait-online 関連

bash
journalctl -b -u NetworkManager-wait-online.service
systemctl status NetworkManager-wait-online.service
nmcli device status
nmcli connection show

依存関係の確認

bash
systemctl list-dependencies --reverse network-online.target

Docker 側の確認候補

bash
journalctl -b -u docker.service
systemctl status docker.service
docker ps -a --format 'table {{.Names}}\t{{.Status}}\t{{.RunningFor}}'
docker network ls

今後の課題

今回のテーマから外れるため深入りはしませんでしたが、今後の課題としては次が考えられます。

  1. Docker 起動時間の内訳を journalctl -b -u docker.service で精査する
  2. Samba コンテナ以外の不要コンテナや不要 network を整理する
  3. NetworkManager-wait-online.service の 5 秒が実運用上不要なら、timeout 方針を再検討する

この記事から得られる知見

本記事の実践的なポイントをまとめると、次のとおりです。

  • boot 遅延調査では、まず critical-chain で本当に遅い鎖を見るべきです
  • NetworkManager-wait-online が遅いときは、NetworkManager が何の profile を待っているかを見るべきです
  • 不要な bridge 設定は、放置すると起動を大きく汚します
  • Docker が遅くても、要件上必要なら「最適化対象外」と明確に切り分けるべきです
  • 見た目が派手な unit に引っ張られず、依存関係と状態を順に追うのが最短です

参考文献

以下は、会話中に参照・確認の土台とした公式ドキュメントです。

  • NetworkManager-wait-online.service

https://networkmanager.pages.freedesktop.org/NetworkManager/NetworkManager/NetworkManager-wait-online.service.html

  • Docker Engine: Start the daemon

https://docs.docker.com/engine/daemon/start/

  • systemd-analyze(1)

https://man7.org/linux/man-pages/man1/systemd-analyze.1.html

  • systemd の drop-in override の考え方の参考

https://www.flatcar.org/docs/latest/setup/systemd/drop-in-units/