Linuxでハングしているプロセスの調査

# 発端

ある日開発用のサーバーを見ると、PostgreSQLのバックアップが動いていないようだ。状況を確認すると、バックアップに使用するpg_rmanプロセスが1か月ほど前からハングして数百個ものプロセスが滞留している。

こんな場合にどこから調査したらいいのか。
Linux初心者の人に向けて、調査した内容をメモする。


# プロセスIDの特定

まずはハングしているプロセスのプロセスIDを`ps`コマンドで特定する。

```
$ ps -ef | grep pg_rman
UID      PID   PPID   C STIME TTY      TIME     CMD
root     17821 27245  4 11:57 pts/0    00:00:01 pg_rman
root     19334 27315  0 11:57 pts/1    00:00:00 grep pg_rman
```

2つ目はgrep自身のプロセスが表示されているだけなので、気にしなくていい。
今回スタックしているプロセスはIDが17821のようだ。
今後の解説ではこのIDをコマンド例に使用する。


# プロセスのリソース使用状況を確認

1か月間止まっているというのはほぼほぼハングと見ていいだろう。
しかし、ハングしているということの裏どりをしなければいけない。まずはプロセスがどんな状態なのかを確認しよう。


## プロセスのCPU使用率

プロセスはスローダウンしているだけで少しは動きがあるのか？それとも完全にハングしているのか？
これをまず確定させねばならない。これをするために以下のような調査を行う。



### リソース使用状況の調査

`top`コマンドを使用してCPU使用率を見てみよう。
もし何もボトルネックがなければCPU使用率は100%になるはずだ。もしI/O待ちなどによって阻害されているのであれば、CPU使用率は非常に低いか、もしくは0%だろう。

```
$ top -cbp 17821
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   5178.1 total,   4016.4 free,    271.3 used,    890.4 buff/cache
MiB Swap:    976.0 total,    976.0 free,      0.0 used.   4646.4 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  17821 root      20   0  164016  10224   7664 S   0.0   0.2   0:04.15 pg_rman
```

一番下の行の`%CPU`の列を見るとCPU使用率は0.0%のようだ。
ただ、ここで0.0%と表示されているからと言って必ずしもプロセスが完全にハングしているわけではないということに注意したい。
topコマンドの出力結果として表示されるCPU使用率は当然ながら四捨五入されているので、もしかしたらすごく低い割合でCPUを使用している可能性はある。
ただ、CPUの能力不足で遅くなっているわけではなさそうなことは分かった。

## プロセスは完全にハングしているのか


### プロセスの詳細なステータスを確認

プロセスIDが分かったら、/procファイルシステムからプロセスの詳細を見てみよう。
Linuxではプロセスの状態はすべて/procの下にファイルとして存在していて、ここから各種の情報を見ることができる。

```
$ cat /proc/17821/status
Name:	pg_rman
State:	D (disk sleep)
Pid:	17821
 :
(省略)
```

これによればプロセスの状態は`D`となっているようだ。
Dというのはuninterruptible wait (割り込み不能な待機状態) を意味し、大抵の場合これはI/O待ちによって発生する。


### コンテキストスイッチの状況確認

コンテキストスイッチというのは、Linuxの処理におけるユーザーモードとカーネルモードの切り替えのことである。
つまり、コンテキストスイッチの回数というのはプロセスの実行がカーネルによって中断された回数である。

コンテキストスイッチを確認するには先ほどのステータスにおける`voluntary_ctxt_switches`と`nonvoluntary_ctxt_switches`の数値を確認する。これはプログラムが動作した状態でLinuxのカーネルが稼働していれば少なからず発生し続けるはずである。

数秒間あけて2回この値を見てみよう。2回目に確認した時にこの回数が増えていないということは少なくともその数秒間はプロセスがまったく動いていないと考えることができる。


ここまでで分かったとことは

**pg_rmanプロセスは**

1. 完全にハングしている
2. ハングしている理由はI/O待ちである

ということである。

# I/O待ちになっている原因を調査する

ちなみに、今回ハングしているpg_rmanはNFS上の領域に対してデータをバックアップするように設定している。
I/O待ちになっているということは、ディスクが壊れてしまったのだろうか?

## NFSの読み取り、書き込みの確認

NFSの領域に対して読み書きが正常にできるかを確認する。

```
# touch /mnt/shared_storage/testfile
# ls -la /mnt/shared_storage
total 4
drwx------  2 root root  4096 Apr  4 10:15 .
drwxr-xr-x  1 root root  4096 Mar 27 20:01 ..
-rw-r--r--  1 root root     0 Mar 11 21:39 testfile
# rm /mnt/shared_storage/testfile
# ls -la /mnt/shared_storage
total 4
drwx------  2 root root  4096 Apr  4 10:15 .
drwxr-xr-x  1 root root  4096 Mar 27 20:01 ..
```

読み取りも書き込みも問題なくできるようだ。

## プロセスのコールスタックを確認

プロセスの状態をもう少し詳細に見ていこう。
/proc/27288/stackを見ることで、システムコールのコールスタックを見ることができる。
コールスタックというのは、プログラムの呼び出し元を辿ったログ表示である。
一番下のプログラム(システムコール)が下から二番目のプログラムを呼び出し、それが下から三番目の・・といった感じだ。

```
# cat /proc/17821/stack
[] rpc_wait_bit_killable+0x24/0x40 [sunrpc]
[] __rpc_execute+0xf5/0x1d0 [sunrpc]
[] rpc_execute+0x43/0x50 [sunrpc]
[] rpc_run_task+0x75/0x90 [sunrpc]
[] rpc_call_sync+0x42/0x70 [sunrpc]
[] nlmclnt_call+0x00/0x80 [nfs]
[] nlmclnt_proc+0xb0/0x90 [nfs]
[] nfs3_proc_lock+0xcc/0x1f0 [nfs]
[] do_setlk+0x36/0x60 [nfs]
[] nfs_flock+0x5f/0x110 [nfs]
[] Sys_flock+0x4e/0x80
[] system_call_fastpath+0x16/0x1b
[] 0xffffffffffffffff
```

最終的には`rpc_wait_bit_killable`でハングしているようだ。
rpcというのはプロセス間通信であり、その応答待ちで止まっていように見える。

ではこのrpcは何によって発生したのか?
4行目に注目して欲しい。`nfs_get_lock`というのがある。
そう、NFSではファイルロックを行う際にrpcを使用していて、その処理の中でハングしているのだ。

## pg_rmanのソースコードを確認する。

GitHubにてpg_rmanのコードを確認する。
確かに、処理の最初でflock(1)を使用していることから、辻褄が合うように見える。
[ossc-db/pg_rman - catalog.c#L54](https://github.com/ossc-db/pg_rman/blob/master/catalog.c#L54)

```c
ret = flock(lock_fd, LOCK_EX | LOCK_NB);	/* non-blocking */
```

## ストレージに対するファイルロックの確認

上の事象の裏取りをしよう。
何か別のプログラムからflockシステムコールを呼び出し、同様にハングするかを確かめたい。
flock(2)というシンプルなコマンドがあり、これを使えば再現できそうだ。
pg_rmanのコード中と同じように、ノンブロッキングのオプション`-n`を付ける。

### flockがハングすることを確認

`flock`コマンドで、NFSの領域に対するファイルロックを試してみる。


```
# flock -n /mnt/shared_storage/testfile.lock echo ok

^C
```

プロンプトが返ってこない。確かにハングしてしまった。

コマンドの`-n`はノンブロッキングモードのオプションであり、すなわちファイルロックが取得できなかった場合に解放を待たずにただちにプログラムを終了する指示である。
つまり、単純にファイルロックが取得できなかったわけではないようだ。

### flockプロセスの状態を確認する

上記のコマンドを実行した状態で別のttyからflockコマンドの状態を確認してみよう。

```
# ps -ef | grep flock
UID      PID   PPID   C STIME TTY      TIME     CMD
root     27288 27245  4 11:57 pts/0    00:00:01 flock -n /mnt/shared_storage/testfile.lock echo ok
root     27334 27315  0 11:57 pts/1    00:00:00 grep flock
# cat /proc/27288/stack
[] rpc_wait_bit_killable+0x24/0x40 [sunrpc]
[] __rpc_execute+0xf5/0x1d0 [sunrpc]
[] rpc_execute+0x43/0x50 [sunrpc]
[] rpc_run_task+0x75/0x90 [sunrpc]
[] rpc_call_sync+0x42/0x70 [sunrpc]
[] nlmclnt_call+0x00/0x80 [nfs]
[] nlmclnt_proc+0xb0/0x90 [nfs]
[] nfs3_proc_lock+0xcc/0x1f0 [nfs]
[] do_setlk+0x36/0x60 [nfs]
[] nfs_flock+0x5f/0x110 [nfs]
[] Sys_flock+0x4e/0x80
[] system_call_fastpath+0x16/0x1b
[] 0xffffffffffffffff
```

見事に同じ状態でハングしている。かなり原因に近づいてきたようだ。

ここまでで分かったとことは

**pg_rmanプロセスは**

1. 完全にハングしている
2. ハングしている理由はI/O待ちである
3. I/O待ちの理由は、flockがハングしていること
4. flockがハングしているのは、rpcの応答待ちになっているから

ということである。

# なぜRPCはハングしているのか

RPCでハングしているということは、何かネットワーク関連で異常がないだろうか?

## tcpdumpによるパケットキャプチャ

正常にflockを行った際のパケットはこちら。

```
```

今回ハングが発生しているサーバーでのパケットキャプチャはこちら。

```
```

正常な場合はnfsの通信の後にsunrpcによる通信を行っているが、異常が発生しているサーバーではそもそもsunrpcの通信が全く行われていない。正確にはrpcの応答待ちではなく、そもそもコネクションを作成できていない状態のようだ。
なぜこのようなことが起きているのだろうか。

## netstatによるコネクション状態の確認

`netstat`コマンドで、ネットワークのコネクションの状態を確認する。

NFSのサーバーのIPアドレスは192.168.11.9として、この通信先に対して何か異常が発生していないかを見たい。

```
# netstat -oa | 192.168.11.9
TCP    192.168.11.5:50888        192.168.11.9:4001         FIN_WAIT_2      3764
```

念のため、しばらく時間をおいてもう一度確認してもこの状態は変わらない。

TCPの説明になってしまうので詳細は省くが、FIN_WAIT2というのはコネクション切断の際にこちらから`FIN`パケットを送り、それに対する`ACK`が返ってきたものの向こうから`FIN`が送られてこない状態である。
通常この状態で長時間止まることはなく、何か異常が発生していることが考えられる。

その後調査を行ったところ、NFSサーバー側のソフトにバグがあり、それが原因で正常にRPC通信ができず、それが原因でファイルロックに失敗していることが判明した。

# まとめ

上記は調査方法の一例である。
何かエラーが起きた時は、1つずつ原因の切り分けと仮説検証を行って原因を絞り込んでいくといいだろう。