#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      -*-

#X 参考情報
crashコマンドの使い方
 psコマンドの使い方
 今さらですがyum