1 はじめに
プロセスがハングアップした場合、その原因調査が必要になるときがあります。
「ハングアップ」とは、例えば、何らかの理由でI/Oが完了せず、I/O完了を待ち続けている状態のことです。
このようなとき、I/O完了待ちプロセスのスタックを調べると、原因究明につながることがあります。
ここでは、httpdプロセスのユーザモード、カーネルモードのスタックの確認方法を説明します。
2 環境
VMware Workstation 14 Playerでゲストマシンを作成しました。
ゲストマシンのOS版数は以下のとおりです。
[root@centos74 ~]# cat /etc/redhat-release
CentOS Linux release 7.4.1708 (Core)
[root@centos74 ~]# uname -r
3.10.0-693.el7.x86_64
3 事前準備
ここでは、httpdを使って、カーネルモード、ユーザモードのスタックを確認してみます。
3.1 httpdパッケージのインストール
[root@centos74 ~]# yum -y install httpd
[root@centos74 ~]# systemctl start httpd
[root@centos74 ~]# ps -C httpd
PID TTY TIME CMD
1095 ? 00:00:00 httpd
1096 ? 00:00:00 httpd
1097 ? 00:00:00 httpd
1098 ? 00:00:00 httpd
1099 ? 00:00:00 httpd
1100 ? 00:00:00 httpd
3.2 httpdのdebuginfoパッケージのインストール
httpdのユーザモードの関数名等を表示するため、httpdのdebuginfoパッケージをインストールします。
httpdパッケージの版数を確認する。
[root@centos74 ~]# rpm -qa|grep httpd
httpd-2.4.6-67.el7.centos.6.x86_64
httpd-tools-2.4.6-67.el7.centos.6.x86_64
httpdパッケージと同じ版数のdebuginfoパッケージをインストールする。
[root@centos74 ~]# yum --enablerepo="base-debuginfo" -y install httpd-debuginfo-2.4.6-67.el7.centos.6.x86_64
パッケージを確認する。httpd-debuginfoがインストールされたことがわかる。
[root@centos74 ~]# rpm -qa|grep httpd
httpd-2.4.6-67.el7.centos.6.x86_64
httpd-debuginfo-2.4.6-67.el7.centos.6.x86_64
httpd-tools-2.4.6-67.el7.centos.6.x86_64
3.3 aprのdebuginfoパッケージのインストール
gstackコマンド(後述)を使うと、スタックトーレスに"libapr"という文字列が表示されました。
httpdがaprの関数を呼び出しているため、aprのdebuginfoパッケージをインストールしました。
aprパッケージの版数を確認する。
[root@centos74 ~]# rpm -qa|grep apr
apr-util-1.5.2-6.el7.x86_64
apr-1.4.8-3.el7_4.1.x86_64
aprパッケージと同じ版数のdebuginfoパッケージをインストールする。
[root@centos74 ~]# yum --enablerepo="base-debuginfo" -y install apr-debuginfo-1.4.8-3.el7.x86_64
パッケージを確認する。apr-debuginfoがインストールされたことがわかる。
[root@centos74 ~]# rpm -qa|grep apr
apr-util-1.5.2-6.el7.x86_64
apr-1.4.8-3.el7_4.1.x86_64
apr-debuginfo-1.4.8-3.el7.x86_64
3.4 glibcのdebuginfoパッケージのインストール
ユーザモードのプロセスは、glibcの関数を経由してシステムコールを間接的に呼び出しています。
したがって、glibcのdebuginfoパッケージをインストールしました。
glibcパッケージの版数を確認する。
[root@centos74 ~]# rpm -qa|grep glibc
glibc-common-2.17-196.el7.x86_64
glibc-headers-2.17-196.el7.x86_64
glibc-debuginfo-2.17-196.el7.x86_64
glibc-2.17-196.el7.x86_64
glibcパッケージと同じ版数のdebuginfoパッケージをインストールする。
[root@centos74 ~]# yum --enablerepo="base-debuginfo" -y install glibc-debuginfo-2.17-196.el7.x86_64
パッケージを確認する。glibc-debuginfoがインストールされたことがわかる。
[root@centos74 ~]# rpm -qa|grep glibc
glibc-common-2.17-196.el7.x86_64
glibc-headers-2.17-196.el7.x86_64
glibc-debuginfo-2.17-196.el7.x86_64
glibc-2.17-196.el7.x86_64
glibc-devel-2.17-196.el7.x86_64
glibc-debuginfo-common-2.17-196.el7.x86_64
4 カーネルモードのスタック確認方法
4.1 psコマンドによる確認方法
psコマンドを使って、httpdプロセスのPID,状態等を確認します。
このとき、psコマンドの出力フォーマットとしてwchanを指定します。
wchanは、プロセスがI/O完了を待つために呼び出したカーネル関数を表示します。
pid=1095のhttpdは、poll_schedule_timeoutを呼び出してI/O完了待ちであることがわかります。
他のhttpdは、inet_csk_acceptを呼び出してI/O完了待ちであることがわかります。
なお、psコマンドの使い方は、ここ(psコマンドの使い方)にあります。
[root@centos74 ~]# ps -C httpd -o comm,pid,ppid,s,wchan
COMMAND PID PPID S WCHAN
httpd 1095 1 S poll_schedule_timeout
httpd 1096 1095 S inet_csk_accept
httpd 1097 1095 S inet_csk_accept
httpd 1098 1095 S inet_csk_accept
httpd 1099 1095 S inet_csk_accept
httpd 1100 1095 S inet_csk_accept
4.2 /procファイルシステムによる確認方法
psコマンドだと、I/O完了待ちをしている関数しかわかりません。
I/O完了待ちに至る関数呼び出しは、/proc/<pid>/stackを確認する必要があります。
ここでは、httpd(pid=1096)プロセスのカーネルモードのスタックを表示してみます。
最終的に、inet_csk_acceptを呼び出していることがわかります。
そして、次に実行する命令のアドレスがffffffff815d65a0であることがわかります。
httpd(pid=1096)のカーネルモードのスタック
[root@centos74 ~]# cat /proc/1096/stack
[<ffffffff815d65a0>] inet_csk_accept+0x230/0x2d0
[<ffffffff8160597c>] inet_accept+0x3c/0x120
[<ffffffff81569e83>] SYSC_accept4+0x103/0x220
[<ffffffff8156b26e>] SyS_accept4+0xe/0x10
[<ffffffff816b4fc9>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff
5 ユーザモードのスタック確認方法
次に、ユーザモードのスタックを確認してみます。
ユーザモードのスタックはgstackコマンドを使って確認します。
main関数を呼び出したあと、最終的にaccept4関数を呼び出していることがわかります。
ただし、apr_socket_acceptの引数が表示されません。理由は現時点で不明。判明次第記載予定。
(他にインストールが必要なdebuginfoがあるのか???)
gstackによるスタックの表示(pid=1096)
[root@centos74 ~]# gstack 1096
#0 0x00007f065a5d5787 in accept4 (fd=4, addr=..., addr_len=0x7fff8bc22a40, flags=524288) at ../sysdeps/unix/sysv/linux/accept4.c:33
#1 0x00007f065acdd43a in apr_socket_accept () from /lib64/libapr-1.so.0
#2 0x00005624e3760123 in ap_unixd_accept (accepted=0x7fff8bc22bc8, lr=0x5624e45be068, ptrans=<optimized out>) at unixd.c:301
#3 0x00007f0651c1d79f in child_main (child_num_arg=child_num_arg@entry=0) at prefork.c:685
#4 0x00007f0651c1da55 in make_child (s=0x5624e45c0330, slot=slot@entry=0) at prefork.c:810
#5 0x00007f0651c1dab6 in startup_children (number_to_start=5) at prefork.c:828
#6 0x00007f0651c1e7c0 in prefork_run (_pconf=<optimized out>, plog=0x5624e45c6378, s=0x5624e45c0330) at prefork.c:986
#7 0x00005624e372915e in ap_run_mpm (pconf=pconf@entry=0x5624e4599158, plog=0x5624e45c6378, s=0x5624e45c0330) at mpm_common.c:96
#8 0x00005624e3721ed6 in main (argc=2, argv=0x7fff8bc22fd8) at main.c:783
6 カーネルモードのスタック確認方法(詳細)
crashコマンドを使って、もう少し詳しく、カーネルモードのスタックを確認してみます。
カーネル関数を表示するため、kernel-debuginfoパッケージをインストールします。
なお、crashコマンドのインストール、使い方はここ(crashコマンドの使い方)を参照してください。
6.1 kernel-debuginfoパッケージのインストール
kernelパッケージの版数を確認する。
[root@centos74 ~]# rpm -qa|grep kernel
kernel-headers-3.10.0-693.el7.x86_64
kernel-tools-libs-3.10.0-693.el7.x86_64
kernel-3.10.0-693.el7.x86_64
kernel-tools-3.10.0-693.el7.x86_64
kernel-devel-3.10.0-693.el7.x86_64
kernelパッケージと同じ版数のdebuginfoパッケージをインストールする。
[root@centos74 ~]# yum --enablerepo=base-debuginfo -y install kernel-debuginfo-3.10.0-693.el7.x86_64
パッケージを確認する。kernel-debuginfoがインストールされたことがわかる。
[root@centos74 ~]# rpm -qa|grep kernel
kernel-headers-3.10.0-693.el7.x86_64
kernel-tools-libs-3.10.0-693.el7.x86_64
kernel-3.10.0-693.el7.x86_64
kernel-tools-3.10.0-693.el7.x86_64
kernel-debuginfo-common-x86_64-3.10.0-693.el7.x86_64
kernel-devel-3.10.0-693.el7.x86_64
kernel-debuginfo-3.10.0-693.el7.x86_64
6.2 I/Oの完了待ちをしている場所の確認
crashコマンドを実行して、ffffffff815d65a0付近の逆アセンブラを表示してみます。
inet_csk_acceptより、schedule_timeoutを呼び出していることがわかります。
ffffffff815d65a0は、I/Oが完了したら、次に実行する命令のアドレスです。
crashコマンドによる確認
[root@centos74 ~]# crash
disコマンドを実行する。-lはソースの行番号を表示するオプションです。
crash> dis -l inet_csk_accept
(中略)
/usr/src/debug/kernel-3.10.0-693.el7/linux-3.10.0-693.el7.x86_64/include/linux/spinlock.h: 351
0xffffffff815d6580 <inet_csk_accept+528>: mov 0x3f8(%r15),%rax
0xffffffff815d6587 <inet_csk_accept+535>: lea 0x10(%rax),%rdi
0xffffffff815d658b <inet_csk_accept+539>: callq 0xffffffff816ab9d0 <_raw_spin_unlock_bh>
0xffffffff815d6590 <inet_csk_accept+544>: jmpq 0xffffffff815d63f0 <inet_csk_accept+128>
0xffffffff815d6595 <inet_csk_accept+549>: nopl (%rax)
/usr/src/debug/kernel-3.10.0-693.el7/linux-3.10.0-693.el7.x86_64/net/ipv4/inet_connection_sock.c: 287
0xffffffff815d6598 <inet_csk_accept+552>: mov %rbx,%rdi
0xffffffff815d659b <inet_csk_accept+555>: callq 0xffffffff816a6da0 <schedule_timeout>
0xffffffff815d65a0 <inet_csk_accept+560>: mov %rax,%rbx
6.3 ソースコードの確認
crashコマンドの実行結果より、I/O完了待ちの場所が287行目ということがわかる。
287行目は、schedule_timeoutを呼び出していることがわかります。
inet_csk_accept@net/ipv4/inet_connection_sock.c
309 struct sock *inet_csk_accept(struct sock *sk, int flags, int *err)
310 {
335 error = inet_csk_wait_for_connect(sk, timeo);
367 }
inet_csk_wait_for_connect@net/ipv4/inet_connection_sock.c
262 static int inet_csk_wait_for_connect(struct sock *sk, long timeo)
263 {
264 struct inet_connection_sock *icsk = inet_csk(sk);
265 DEFINE_WAIT(wait);
266 int err;
267
268 /*
269 * True wake-one mechanism for incoming connections: only
270 * one process gets woken up, not the 'whole herd'.
271 * Since we do not 'race & poll' for established sockets
272 * anymore, the common case will execute the loop only once.
273 *
274 * Subtle issue: "add_wait_queue_exclusive()" will be added
275 * after any current non-exclusive waiters, and we know that
276 * it will always _stay_ after any new non-exclusive waiters
277 * because all non-exclusive waiters are added at the
278 * beginning of the wait-queue. As such, it's ok to "drop"
279 * our exclusiveness temporarily when we get woken up without
280 * having to remove and re-insert us on the wait queue.
281 */
282 for (;;) {
283 prepare_to_wait_exclusive(sk_sleep(sk), &wait,
284 TASK_INTERRUPTIBLE);
285 release_sock(sk);
286 if (reqsk_queue_empty(&icsk->icsk_accept_queue))
287 timeo = schedule_timeout(timeo); ★
288 lock_sock(sk);
289 err = 0;
290 if (!reqsk_queue_empty(&icsk->icsk_accept_queue))
291 break;
292 err = -EINVAL;
293 if (sk->sk_state != TCP_LISTEN)
294 break;
295 err = sock_intr_errno(timeo);
296 if (signal_pending(current))
297 break;
298 err = -EAGAIN;
299 if (!timeo)
300 break;
301 }
302 finish_wait(sk_sleep(sk), &wait);
303 return err;
304 }
7 補足
debuginfoパッケージインストールすると、/usr/src/debug配下にソースが展開されます。
glibcの場合
[root@centos74 glibc-2.17-c758a686]# pwd
/usr/src/debug/glibc-2.17-c758a686
[root@centos74 glibc-2.17-c758a686]# ls -F
argp/ ctype/ gshadow/ io/ misc/ pwd/ shadow/ sunrpc/ wctype/
assert/ debug/ hesiod/ libidn/ nis/ releng/ signal/ sysdeps/
bits/ dirent/ iconv/ libio/ nptl/ resolv/ socket/ sysvipc/
build-x86_64-redhat-linux/ dlfcn/ iconvdata/ locale/ nptl_db/ resource/ stdio-common/ termios/
catgets/ elf/ include/ login/ nscd/ rt/ stdlib/ time/
crypt/ gmon/ inet/ malloc/ nss/ rtkaio/ streams/ timezone/
csu/ grp/ intl/ math/ posix/ setjmp/ string/ wcsmbs/
aprの場合
[root@centos74 apr-1.4.8]# pwd
/usr/src/debug/apr-1.4.8
[root@centos74 apr-1.4.8]# ls -F
atomic/ file_io/ locks/ misc/ network_io/ poll/ shmem/ support/ threadproc/ user/
dso/ include/ memory/ mmap/ passwd/ random/ strings/ tables/ time/
8 まとめ
httpdプロセス(pid=1096)は、ユーザモード、カーネルモードにおいて、
下記のように関数を呼び出して、I/O完了待ちの状態になっていることがわかりました。
main -*-
+ ap_run_mpm |
+ prefork_run |
+ startup_children |
+ make_child ユーザモードのスタック
+ child_main |
+ ap_unixd_accept |
+ apr_socket_accept |
+ accept4 -*-
+ system_call_fastpath -*-
+ SyS_accept4 |
+ SYSC_accept4 カーネルモードのスタック
+ inet_accept |
+ inet_csk_accept |
+ schedule_timeout -*-