発端
ある日開発用のサーバーを見ると、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プロセスは
- 完全にハングしている
- ハングしている理由は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
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プロセスは
- 完全にハングしている
- ハングしている理由はI/O待ちである
- I/O待ちの理由は、flockがハングしていること
- 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つずつ原因の切り分けと仮説検証を行って原因を絞り込んでいくといいだろう。