背景
諸事情あり、Ubuntuサーバの停止時間の詳細分析をする必要に迫られまして。
これまでは漠然と「サービスとカーネルがなんかしてるんだろう」という認識だったのですが、そうも言ってられないので、調べものしてみました。
結論としては、権威ある文書などは見つけられておらず、実測して色々考えた情報をまとめるだけになってしまいました。。
基礎知識
最近のUbuntuではサービスはsytemdで管理されており、サービス同士の依存関係や起動順序はユニットファイルとやらで定義されているんだそうで。
終了時も、この起動順序を逆順にしながら終了していくようです。
順序関係がないものは並行で終了処理。
単純に処理の遅いものが全体の停止の足を引っ張るわけではない、ということですね。
タイプ
systemdで管理されているものとして、例えばWebサーバのApachのような常駐プロセスをイメージしていたのですが、そういうものだけではないらしく。
manの情報を引用するとこんな。
The following unit types are available:
1. Service units, which start and control daemons and the processes they consist of. For details, see
systemd.service(5).
2. Socket units, which encapsulate local IPC or network sockets in the system, useful for socket-based
activation. For details about socket units, see systemd.socket(5), for details on socket-based activation
and other forms of activation, see daemon(7).
3. Target units are useful to group units, or provide well-known synchronization points during boot-up, see
systemd.target(5).
4. Device units expose kernel devices in systemd and may be used to implement device-based activation. For
details, see systemd.device(5).
5. Mount units control mount points in the file system, for details see systemd.mount(5).
6. Automount units provide automount capabilities, for on-demand mounting of file systems as well as
parallelized boot-up. See systemd.automount(5).
7. Timer units are useful for triggering activation of other units based on timers. You may find details in
systemd.timer(5).
8. Swap units are very similar to mount units and encapsulate memory swap partitions or files of the
operating system. They are described in systemd.swap(5).
9. Path units may be used to activate other services when file system objects change or are modified. See
systemd.path(5).
10. Slice units may be used to group units which manage system processes (such as service and scope units) in
a hierarchical tree for resource management purposes. See systemd.slice(5).
11. Scope units are similar to service units, but manage foreign processes instead of starting them as well.
See systemd.scope(5).
当初想定していた常駐プロセスに該当するのは"1.service"ですね。
厄介ですが、上記11タイプについて網羅して考えないといけないようです。。
まぁ、１つ１つやってみますか。
systemd関連ログ
今回やりたいのは、各サービスの「終了にかかる時間」の計測です。
systemd関連のコマンド(systemd-analyzeとか)でいい感じに終了所要時間を図ってくれるものがないかなぁ、、、と思ったのですが、見つけられませんでしたので、ログベースで調べる方法をまとめていこうと思います。
systemdのログは、基本journallogで管理していて、サービスごとにふるい分けて表示する場合は
$ sudo journalctl -u <サービス名>
とすることになります。
各サービスの終了開始/終了完了の際に出るログがどんなものなのかがわかれば、そのログのタイムスタンプの差分を取ることで個別のサービスの終了所要時間がわかる、、はです。
ということで、今回は上記のタイプごとに、どんなログの出方をするのかを色々調べてみようと思います。
タイプごとの終了開始/完了時のログ
1. XXX.service
自分のサーバのログを読み込んで見ると、いくつかパターンがあるみたいです。
終了開始/完了時にきれいにログが出るパターン
$ sudo journalctl -u blk-availability.service
...
Aug 28 04:41:50 nms systemd[1]: Stopping Availability of block devices...
Aug 28 04:41:50 nms blkdeactivate[972]: Deactivating block devices:
Aug 28 04:41:50 nms systemd[1]: blk-availability.service: Deactivated successfully.
Aug 28 04:41:50 nms systemd[1]: Stopped Availability of block devices.
...
まず停止処理を開始するときに出るのがStopping 。
サービス内で停止中にログを吐くときは、それも表示。
停止完了すると、<サービス名>: Deactivated sucessfullyとStopped 。
表示がサービス名とDescription(該当サービスのUnitファイルで定義したもの)の両方使われるのがなんともめんどくさいですが、、、Stopping〜Stoppedでgrepしてタイムスタンプの差分を取れば、停止にかかった所要時間を導き出せそうです。
こういうケースだけだったら良かったのですが、、そうでもなかったんですよねぇ。。
終了完了のログしか出ないパターン
$ sudo journalctl -u cloud-config.service
...
Aug 28 04:41:50 nms systemd[1]: cloud-config.service: Deactivated successfully.
Aug 28 04:41:50 nms systemd[1]: Stopped Apply the settings specified in cloud-config.
...
手元でいくつかユニットファイル作って試してみたのですが、結論としては、上記の出方をするのは以下のケースのようです。
- ExecStartで実施しているのがワンショットの処理 (プロセスは常駐していない)
- その上で、ExecStopを定義していない
サービス停止時は建前上Stop処理をするけど、対象のプロセスはもともと終了しているので、終了処理を何もしなくていいのでStoppingも出ない、、ということでしょうか。
プロセスが常駐する場合や、常駐はしないけれどExecStopが定義されている場合はStoppingが出るようです。
今回の趣旨の「終了にかかる時間の計測」という観点では、「所要時間0」と判断するようにすればいいか。
2. XXX.socket
systemd.socketのmanページより。
For each socket unit, a matching service unit must exist, describing the service to start on incoming traffic on the socket
別途対応する.serviceがあって、それを呼び出す、ということですね。
、、となると、終了時間の計測という観点では、.serviceの方だけ確認しておけばいいかな。
ちなみにログはこんなです。
$ sudo journalctl -u systemd-networkd.socket
Aug 28 04:41:50 nms systemd[1]: systemd-networkd.socket: Deactivated successfully.
Aug 28 04:41:50 nms systemd[1]: Closed Network Service Netlink Socket.
3. XXX.target
..., which is used for grouping units and as well-known synchronization points during start-up
そもそもXXX.targetはサービス群をグルーピングして順序制御などをするための概念、、だと思います。
なので、今回の集計では一旦対象外でいいかな。
ただし、次のステップでサービス同士の停止順序を加味して考える際は、各グループが終了を終えたマイルストーンを見る、という意味で改めて使うかもです。
$ sudo systemctl -u basic.target
Aug 28 04:41:50 nms systemd[1]: Stopped target Basic System.
4. XXX.device
A unit configuration file whose name ends in ".device" encodes information about a device unit as exposed in the sysfs/udev(7) device tree. This may be used to define dependencies between devices and other units.
わからん、、、動的に生成されてるっぽい雰囲気なのですが、、
ぐぐったら以下が非常に参考になりました、、が、今回用途の答えには至れず。
https://enakai00.hatenablog.com/entry/20130916/1379295816
終了の際にどういう振る舞いをするのかが気になりますが、ログは何も出ないんですよね。。
$ sudo journalctl -u sys-devices-platform-serial8250-tty-ttyS1.device
-- No entries --
.deviceにはNICやシリアルも入っているようです。
$ systemctl list-units --type device
UNIT
...
sys-devices-platform-serial8250-tty-ttyS1.device loaded active plugged /sys/d>
sys-subsystem-net-devices-enp7s0.device loaded active plugged Virtio>
...
通信しまくっている最中だと遅くなったりしないのかな、、というのがちょっと怖いです。
networkについて言えば、別途serviced-netw0rkd.serviceで終了状況はわかるんですけど。
調べた感じ何も情報が得られなかったので、一旦調査打ち切り。
懸念はしておくけど、計測対象外で！！
5. XXX.mount
$ sudo journalctl -u run-snapd-ns-lxd.mnt.mount
...
Aug 28 04:41:50 nms systemd[1]: Unmounting /run/snapd/ns/lxd.mnt...
Aug 28 04:41:50 nms systemd[1]: run-snapd-ns-lxd.mnt.mount: Deactivated successfully.
Aug 28 04:41:50 nms systemd[1]: Unmounted /run/snapd/ns/lxd.mnt.
...
ちゃんと終了開始と、終了完了が出てくれるっぽいですね。
6. XXX.automount
$ sudo journalctl -u proc-sys-fs-binfmt_misc.automount
Aug 28 04:41:50 nms systemd[1]: proc-sys-fs-binfmt_misc.automount: Deactivated successfully.
Aug 28 04:41:50 nms systemd[1]: Unset automount Arbitrary Executable File Formats File System Automount Point.
Automountはググった感じ、使うときにはXXX.mountもセットで作るらしいです。
必要になったらマウントするためのもの。
終了時は、起動中にmountされてたら、アンマウントの処理が動く、、てことでしょうか。
mount側のログだけ見てればいいかな。
こちらのAutomountの終了処理で時間がかかることはないとは思う（根拠なし！！）ので、計測対象外！！
7. XXX.timer
$ sudo journalctl -u apt-daily-upgrade.timer
1182 Aug 28 04:41:50 nms systemd[1]: apt-daily-upgrade.timer: Deactivated successfully.
1183 Aug 28 04:41:50 nms systemd[1]: Stopped Daily apt upgrade and clean activities.
調べた感じ、automountと同じように実態は別にXXX.serviceとして定義されていて、指定タイミングでそいつを呼び出す、と言うもののようです。
常駐しているプログラムではないですけれど、ちょうどshutdown中にかぶるとどうなる、、？という懸案はあるっちゃあります。
ちなみに該当するサースのログはこちら。
$ sudo journalctl -u apt-daily.service
Aug 20 08:09:39 nms systemd[1]: Starting Daily apt download activities...
Aug 20 08:09:42 nms systemd[1]: apt-daily.service: Deactivated successfully.
Aug 20 08:09:42 nms systemd[1]: Finished Daily apt download activities.
Aug 20 08:09:42 nms systemd[1]: apt-daily.service: Consumed 2.780s CPU time.
timer自体は計測対象外。
ただし、timerが呼び出すプロセスについては停止処理の計測とは別に取得しておいて、最悪停止のタイミングとかぶると何秒追加になる、というように管理するようにしますか。
8. XXX.swap
これも自動生成、、なのかな。。
manを見るにloca-fsを対比で書いていて、deviceと似たような感じがします。
$ sudo journalctl -u swap.img.swap
Aug 28 11:46:41 nms systemd[1]: swap.img.swap: Deactivated successfully.
Aug 28 11:46:41 nms systemd[1]: Deactivated swap /swap.img.
処理時間がっかることがあるのかないのかなんともですが、、
deviceとセットで要注意で観察しますが、一旦計測対象外で。
9. XXX.path
$ sudo journalctl -u systemd-ask-password-console.path
Aug 28 04:41:50 nms systemd[1]: systemd-ask-password-console.path: Deactivated successfully.
Aug 28 04:41:50 nms systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
pathとはなんぞやというと、、ざっくりですが、所定のパスの変化を監視して、変化があったら所定の動作をする、でしょうか。
そのような処理が終了に時間かかるとも思わないですし、これも計測対象外でいいかな。
10. XXX.slice
A slice unit is a concept for hierarchically managing resources of a group of processes.
ということで、targetと同じく、集計対象外で。
11. XXX.scope
manをみるに、systemdが自動で作る、、とあります。
init.scopeの中身とかは他のunitのログがまとまって入ってたりする感じです。
個別のserviceやマウントで見ればいいかな、、という気がするので、集計対象外で。
備考 上記を調べるにあたって
一回以下のコマンドでサーバ終了間際のログを引っこ抜いて、それを眺めながら調査してました。
$ sudo systemctl list-units --plain --no-pager --no-legend \
| cut -d " " -f 1 \
| while read unit; do
echo $unit
journalctl --no-pager --since "2022-08-28 04:41:49" --until "2022-08-28 04:41:51" -u $unit;
echo
done
それぞれのユニットの中を見たいときは以下。
$ sudo systemctl cat <ユニット名>
$ sudo systemctl show <ユニット名>
サービスの終了に対する留意点
上記でとりあえずタイプごとの終了開始/完了を見る方法が整理できそうです。
ただし、実際のログを見る際は、もう１つ注意しないといけないものがあります。
なにかというと、「タイムアウト」。
unitfileの中に"TimeoutStopSec=90"という形で定義したりしなかったりします。
標準は90秒。
systemctl show <サービス名> した場合は、"TimeoutStopUSec=30s"などと表示されます。
(TimeoutStop"U"Secを使うのが正しい、、のかな、、？)
さておき。
停止処理に時間がかかってこのタイムアウトを超えてしまうと、以下のようなログの出方になります。
Aug 28 12:25:25 nms systemd[1]: test01.service: Stopping timed out. Terminating.
Aug 28 12:25:25 nms systemd[1]: test01.service: Control process exited, code=killed, status=15/TERM
Aug 28 12:25:25 nms systemd[1]: test01.service: Failed with result 'timeout'.
Aug 28 12:25:25 nms systemd[1]: Stopped Test Service 01.
最後はStoppedで終わってくれるですが、Deactivatedの行はでなくなります。
また、サービスから見れば基本的には強制終了で終わりたくはないですから、Timeoutを伸ばしてやる、という調整をしたほうがいいのかもしれません。
逆に実装が悪くて待つ必要もないのにダラダラ終了するやつは強制終了でいいでしょうし。
ということで、タイムアウトしてしまっているケースも明確に拾ってあげないといけないですね。。
以上踏まえて、サービスごとの終了時間計測
上記を踏まえて、スクリプトにしておこう、、としたのですが、Stoppingの前にサービス自体のログが入るパターンや、runningのサービスなのですがなんも停止ログが出ないものなどがあり、もうちょっと煮詰めないとだめっぽいです。
後日作っときます。。
とりあえず作りかけを貼っときます。
TMP=`mktemp /tmp/temp.XXXXXX`
function check () {
SLINE=`head -n 1 $TMP`
LLINE=`tail -n 1 $TMP`
L2LINE=`tail -n +2 $TMP`
if [[ "$SLINE" =~ ^.*[^\S]systemd\[[0-9]+\]:[^\S]Stopping[^\S].*$ ]]; then
STIME=`echo "$SLINE" | sed -r "s/.* ([0-9:]+) .*/\1/"`
else
echo "$1,,,Format Error"
cat $TMP
return 0
fi
if [[ "$LLINE" =~ ^.*[^\S]systemd\[[0-9]+\]:[^\S]Stopped[^\S].*$ ]]; then
LTIME=`echo "$SLINE" | sed -r "s/.* ([0-9:]+) .*/\1/"`
else
echo "$1,,,Format Error"
cat $TMP
return 0
fi
if [[ "$L2LINE" =~ ^.*[^\S]systemd\[[0-9]+\]:[^\S].*Deactivated[^\S]successfully\. ]]; then
echo "$1,$STIME,$LTIME"
else
echo "$1,$STIME,$LTIME,Exceed Timeout!!"
fi
return 0
}
sudo systemctl list-units --type=service --state running \
--plain --no-pager --no-legend \
| cut -d " " -f 1 \
| while read unit; do
sudo journalctl --no-pager --since "2022-08-28 04:41:49" --until "2022-08-28 04:41:51" -u $unit > $TMP
check $unit
echo
done
rm $TMP
"--state runnning"以外は、上記のstoppingが出ないパターンになると思ってます。
で、あとはmountの処理と、timerから呼び出される分の参考値を表示させればOK。