☰

Debian 10 で終了 1 分 30 秒間、「ジョブの実行を中止する」分析

tag-icon • tag-icon debian systemd logs
Debian 10 で終了 1 分 30 秒間、「ジョブの実行を中止する」分析

Debian 10デスクトップバージョンをインストールしました。 1分30秒ほど遅れるなど、終了が頻繁に遅れることを確認しました。 Debian 9 のインストールではこの問題は発生しません。 （または少なくとも少ない頻度）。

journalctl後でシステムログを見ると、遅延（）も表示されます。このログを分析したいです。

場合によっては、ユーザーサービスに問題があるようですpulseaudio.service。その場合はTimeoutStopSec=2、サービス設定などを使用してこの問題を簡単に解決できます。 （これはシステムサービスではなくユーザーサービスです。システムサービスはありませんpulseaudio.service。）

私が見た2番目のケースでは、pulseaudio.serviceリクエストするとすぐに終了するようです。もしそうなら、タイムアウトを設定しても役に立ちません:-)。代わりに、pulseaudio.servicesystemdが停止を要求するまでに長い遅延があるようです。 2番目のログを見ると、何が問題なのかわかりません。

うまくいくためのより広範な解決策があります（最後を参照）。ところで、具体的に何が問題なのか知りたいです。

質問

  1. 下の2番目のログには、私が特定できなかった特定の問題が表示されますか？
  2. ソフトウェアのバグが原因で次のログが発生する可能性があり、ログ内の特定の問題を特定できないと予想または既知の状況がありますか？

私の現在のsystemdパッケージバージョンはです241-5。

修正する

私の考えでは、この質問は以下に関連しているようです。問題 #12262。この問題に対する解決策は「cgroup-util：スレッドも終了します」（広報＃12621）、システムバージョン243にマージされました。

PRリンクの議論によると、バグはcgroupsv2（「統合制御グループ階層」）に固有のものです。 Debian 10 は cgroupsv2 を使用しますが、Debian 9 は使用しません。具体的には、Debian 10 は以下を使用します。過渡的な「ハイブリッド」階層。

systemd.legacy_systemd_cgroup_controllerだからカーネルブートオプションを追加してみました。このオプションを使用すると、cgroup2ファイルシステムがどこにもマウントされておらず、マウントのみになっていることがわかりますcgroup。残念ながら、まだ説明できない終了遅延が表示されます。

完全なログ：ログ終了遅延 2.txt

Sep 08 16:24:25 drystone kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-4.19.0-5-amd64 root=UUID=f10753fb-0a2d-4288-971d-5f33682ab5c0 ro systemd.legacy_systemd_cgroup_controller quiet

Sep 08 16:54:28 drystone systemd[1]: Stopped Firmware update daemon.
Sep 08 16:55:58 drystone systemd[1442]: Stopping D-Bus User Message Bus...
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Default.
Sep 08 16:55:58 drystone systemd[1442]: Stopping Sound Service...
Sep 08 16:55:58 drystone systemd[1442]: pulseaudio.service: Succeeded.
Sep 08 16:55:58 drystone systemd[1442]: Stopped Sound Service.
Sep 08 16:55:58 drystone systemd[1442]: dbus.service: Main process exited, code=killed, status=15/TERM
Sep 08 16:55:58 drystone systemd[1442]: dbus.service: Succeeded.
Sep 08 16:55:58 drystone systemd[1442]: Stopped D-Bus User Message Bus.
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Basic System.
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Paths.
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Timers.

また、PRディスカッションによると、代替の修正方法はLinuxカーネルバージョン5.2以降を使用することです。カーネル修正コミットは次のとおりです。"cgroup：PROCS反復でアクティブなスレッドを持つ死んだリーダーが含まれています。"。これは安定カーネルシリーズ4.19.xにも含まれています。これ安定したコミット日付は2019年6月10日です。しかし、この記事を書いている時点で、現在のDebian 10カーネルは4.19.67基準、公開2019-04-27頃。したがって、この Debian カーネルにはまだ修正は含まれていません。

1.パルスオーディオ終了遅延

Aug 31 08:40:28 drystone systemd[1862]: Stopped target Default.
Aug 31 08:40:28 drystone systemd[1862]: Stopping Sound Service...
Aug 31 08:40:28 drystone systemd[1]: Stopping User Manager for UID 1005...

...

Aug 31 08:41:57 drystone systemd[1862]: Stopping D-Bus User Message Bus...
Aug 31 08:41:57 drystone systemd[1862]: pulseaudio.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1862]: Stopped Sound Service.
Aug 31 08:41:57 drystone systemd[1862]: dbus.service: Main process
exited, code=killed, status=15/TERM
Aug 31 08:41:57 drystone systemd[1862]: dbus.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1862]: Stopped D-Bus User Message Bus.
Aug 31 08:41:57 drystone systemd[1862]: Stopped target Basic System.

...

Aug 31 08:41:57 drystone systemd[1862]: Reached target Shutdown.
Aug 31 08:41:57 drystone systemd[1862]: systemd-exit.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1862]: Started Exit the Session.
Aug 31 08:41:57 drystone systemd[1862]: Reached target Exit the Session.
Aug 31 08:41:57 drystone systemd[1863]:
pam_unix(systemd-user:session): session closed for user mike

...

Aug 31 08:41:57 drystone systemd[1]: [email protected]: Succeeded.
Aug 31 08:41:57 drystone systemd[1]: Stopped User Manager for UID 1005.

2. 説明できない終了遅延

完全なログ：ログ終了遅延.txt

Sep 03 11:42:47 drystone systemd[1]: Stopping User Manager for UID 1001...

...

Sep 03 11:42:47 drystone systemd[1]: Stopped Login Service.
Sep 03 11:44:16 drystone systemd[1359]: Stopping D-Bus User Message Bus...
Sep 03 11:44:16 drystone systemd[1359]: Stopping Sound Service...
Sep 03 11:44:16 drystone systemd[1359]: pulseaudio.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Stopped Sound Service.
Sep 03 11:44:16 drystone systemd[1359]: dbus.service: Main process exited, code=killed, status=15/TERM
Sep 03 11:44:16 drystone systemd[1359]: dbus.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Stopped D-Bus User Message Bus.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Basic System.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Sockets.
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent and passphrase cache.
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent-ssh.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Sep 03 11:44:16 drystone systemd[1359]: dbus.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed D-Bus User Message Bus Socket.
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent-browser.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent-extra.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Sep 03 11:44:16 drystone systemd[1359]: dirmngr.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG network certificate management daemon.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Timers.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Paths.
Sep 03 11:44:16 drystone systemd[1359]: pulseaudio.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed Sound System.
Sep 03 11:44:16 drystone systemd[1359]: Reached target Shutdown.
Sep 03 11:44:16 drystone systemd[1359]: systemd-exit.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Started Exit the Session.
Sep 03 11:44:16 drystone systemd[1359]: Reached target Exit the Session.
Sep 03 11:44:16 drystone systemd[1360]: pam_unix(systemd-user:session): session closed for user alan-sysop
Sep 03 11:44:16 drystone systemd[1]: [email protected]: Succeeded.
Sep 03 11:44:16 drystone systemd[1]: Stopped User Manager for UID 1001.

公開：このリンクログには、systemd[1]: Received SIGINT. Ctrl + Alt + Delを押しながら作成した13行も含まれています。私が知っている限り、これはPlymouthブートスプラッシュを切り替える以外には効果がありません。最初のメッセージは、システムが30秒間停止した後に表示されます。だから私たちはそれを無視できると思います。

pulseaudio.service を遅延させるソート依存関係が見つかりません。

サービスファイルには、次の明示的な順序依存関係はありませんpulseaudio.service。

$ grep -r pulseaudio.service /usr/lib/systemd/user/
$

その逆:

$ systemctl --user cat pulseaudio.service
# /usr/lib/systemd/user/pulseaudio.service
[Unit]
Description=Sound Service

# We require pulseaudio.socket to be active before starting the daemon, because
# while it is possible to use the service without the socket, it is not clear
# why it would be desirable.
#
# A user installing pulseaudio and doing `systemctl --user start pulseaudio`
# will not get the socket started, which might be confusing and problematic if
# the server is to be restarted later on, as the client autospawn feature
# might kick in. Also, a start of the socket unit will fail, adding to the
# confusion.
#
# After=pulseaudio.socket is not needed, as it is already implicit in the
# socket-service relationship, see systemd.socket(5).
Requires=pulseaudio.socket
ConditionUser=!root

[Service]
# Note that notify will only work if --daemonize=no
Type=notify
ExecStart=/usr/bin/pulseaudio --daemonize=no
Restart=on-failure

[Install]
Also=pulseaudio.socket
WantedBy=default.target

現在試している回避策

diff --git a/systemd/system/[email protected]/override.conf b/systemd/system/[email protected]/override.conf
new file mode 100644
index 0000000..86734ef
--- /dev/null
+++ b/systemd/system/[email protected]/override.conf
@@ -0,0 +1,2 @@
+[Service]
+TimeoutStopSec=7s
diff --git a/systemd/user.conf b/systemd/user.conf
index b427f1e..cb5b646 100644
--- a/systemd/user.conf
+++ b/systemd/user.conf
@@ -21,7 +21,7 @@
 #DefaultStandardOutput=inherit
 #DefaultStandardError=inherit
 #DefaultTimeoutStartSec=90s
-#DefaultTimeoutStopSec=90s
+DefaultTimeoutStopSec=5s
 #DefaultRestartSec=100ms
 #DefaultStartLimitIntervalSec=10s
 #DefaultStartLimitBurst=5

ベストアンサー1

具体的に何が問題なのか知りたいです。

さまざまな回避策を適用した後にこの問題が発生したとき、systemdその問題は- :-)にのみ発生すると言われましたsystemd。

特に、システム管理者はUser Managerを終了する必要がありました。 「ユーザーマネージャ」には待機中の子プロセスはありません。それ以外の場合は、ログにそのユーザーも死亡したとマークされます。

もちろん、バグがsystemdではなくカーネルにある可能性はまだあります。

Sep 13 20:21:58 drystone systemd[1]: Stopping User Manager for UID 1005...
Sep 13 20:21:58 drystone systemd[1531]: Stopping Sound Service...
Sep 13 20:22:05 drystone systemd[1]: [email protected]: State 'stop-sigterm' timed out. Killing.
Sep 13 20:22:05 drystone systemd[1]: [email protected]: Killing process 1531 (systemd) with signal SIGKILL.
Sep 13 20:22:05 drystone systemd[1]: [email protected]: Main process exited, code=killed, status=9/KILL
Sep 13 20:22:05 drystone systemd[1]: [email protected]: Failed with result 'timeout'.
Sep 13 20:22:05 drystone systemd[1]: Stopped User Manager for UID 1005.

これはpulseaudioも終了する例です。このログも非常に奇妙です。システム管理者はユーザー管理者に停止を要求しましたが、ユーザー管理者はどのユーザーにも停止を要求しませんでした。

Sep 20 19:47:46 drystone systemd[1]: Stopping User Manager for UID 1005...
Sep 20 19:47:53 drystone systemd[1]: [email protected]: State 'stop-sigterm' timed out. Killing.
Sep 20 19:47:53 drystone systemd[1]: [email protected]: Killing process 1459 (systemd) with signal SIGKILL.
Sep 20 19:47:53 drystone systemd[1]: [email protected]: Killing process 1551 (pulseaudio) with signal SIGKILL.
Sep 20 19:47:53 drystone systemd[1]: [email protected]: Main process exited, code=killed, status=9/KILL
Sep 20 19:47:53 drystone systemd[1]: [email protected]: Failed with result 'timeout'.
Sep 20 19:47:53 drystone systemd[1]: Stopped User Manager for UID 1005.

おすすめ記事