Apache+PHPを動かしているサーバで、負荷急上昇が起こりました。
サーバ再起動したら解決したのですが、原因としては何が考えられるでしょうか？
(このときのページビューなどはいつも通りでした)
sar -q
17時40分01秒 runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15
20時40分06秒 2 185 1.71 0.63 0.27
21時03分02秒 32 189 83.54 77.51 56.19
21時20分01秒 0 186 4.18 25.29 41.41
sar -p
17時40分01秒 CPU %user %nice %system %iowait %steal %idle
20時40分06秒 all 6.51 0.00 2.46 3.20 0.00 87.83
21時03分02秒 all 2.34 0.00 90.84 3.92 0.00 2.90
21時20分01秒 all 5.61 0.00 48.84 12.57 0.00 32.98
21時30分01秒 all 8.85 0.00 3.76 9.99 0.00 77.40
※レイアウトが崩れて見にくいのでgistにもコピペしました。
https://gist.github.com/DQNEO/5036078
sar -q
17時40分01秒 runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15
20時40分06秒 2 185 1.71 0.63 0.27
21時03分02秒 32 189 83.54 77.51 56.19
21時20分01秒 0 186 4.18 25.29 41.41
sar -p
17時40分01秒 CPU %user %nice %system %iowait %steal %idle
20時40分06秒 all 6.51 0.00 2.46 3.20 0.00 87.83
21時03分02秒 all 2.34 0.00 90.84 3.92 0.00 2.90
21時20分01秒 all 5.61 0.00 48.84 12.57 0.00 32.98
21時30分01秒 all 8.85 0.00 3.76 9.99 0.00 77.40
sar -r
17時40分01秒 kbmemfree kbmemused %memused kbbuffers kbcached kbswpfree kbswpused %swpused kbswpcad
20時00分01秒 1092004 2952716 73.00 163956 1465984 2121924 30776 1.43 11400
20時10分01秒 284856 3759864 92.96 163956 1467096 2121924 30776 1.43 11400
20時20分01秒 30936 4013784 99.24 161348 1225860 2121924 30776 1.43 10788
20時30分01秒 53648 3991072 98.67 155348 1051588 2121924 30776 1.43 10696
20時40分06秒 49648 3995072 98.77 2400 47432 1008068 1144632 53.17 311328
21時03分02秒 151380 3893340 96.26 428 28568 0 2152700 100.00 4520
21時20分01秒 25776 4018944 99.36 1744 41660 60352 2092348 97.20 427144
21時30分01秒 578288 3466432 85.70 5020 53940 1340088 812612 37.75 377420
21時40分01秒 27780 4016940 99.31 5864 58824 1545472 607228 28.21 342024
21時50分01秒 161608 3883112 96.00 3220 47796 1459808 692892 32.19 236504
No.1
4969
2152
100pt
21:03 近辺のことを言ってるんですよね。
%user ではなく、%system が振りきれてて、%swpused が 100% になってる。
メモリを大量に要求する処理が走って、他が動けなくなっている。
いや、ldavg-1 が急に大きくなったということは、たくさんの処理を実行しようとしていた、かな。
いや、プロセスの起動が多いなら、こんなに %system の割合が大きくはならないかな。
もうちょっと、%user とか %iowait の割合が上がる気がします。
「サーバ再起動」と言ってるのは、OS の再起動ではなく、apache を再起動した、ということでしょうか？
もし、apache の再起動で回復した、ということであれば、20:30 くらいから 21:03 までの accesslog をチェックしましょう。
公開しているサーバであれば、アタックの可能性もあります。
クローズドなネットワークであれば、accesslog から処理を特定して、アプリケーションの処理を確認。
ループしてリクエストを投げてくるようなクライアントアプリとか、無限に子プロセスを作り続けるようなサーバ処理とか。
20:30 くらいから、と書いたのはスワップの空き領域が目立って減り始めた時刻としてなのですが、予兆は 20:10～20:20 くらいからあったのかもしれません。
もし、再起動したのが apache ではなく OS なのだとしたら、原因となったプロセスの特定ができません。
問題が再現したときに、ps コマンドでプロセスの数と、使用メモリサイズを確認して、問題を起こしたプロセスを特定するようにしましょう。
続報です。
/var/log/messagesに何か出てました。
OOM Killer という仕組みがプロセスを殺してます。
メモリが足りなくなってきたときに、殺すとメモリをたくさん解放してくれそうなプロセスを殺してくれます。
何で、irqbalance なんかが殺されなきゃいけないんだろうというのはありますが、20:46:56 に apache が殺されてるので、ここから復旧した、という感じなんでしょうか？
Feb 23 20:46:56 web1 kernel: Out of memory: Killed process 5692 (httpd). Feb 23 20:46:56 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0
/var/log/messages に、↑以降の時間で、同じようなメッセージが出ていなければ、メモリを馬鹿食いしていたプロセスは httpd (apache) に決まりですね。
sar -r の結果だと、20:03:02 で swapfree がゼロなので、もしかしたら他にメモリを食ってたやつがいる可能性があります。
No.1
49692152
ここでベストアンサー
100pt
21:03 近辺のことを言ってるんですよね。
%user ではなく、%system が振りきれてて、%swpused が 100% になってる。
メモリを大量に要求する処理が走って、他が動けなくなっている。
いや、ldavg-1 が急に大きくなったということは、たくさんの処理を実行しようとしていた、かな。
いや、プロセスの起動が多いなら、こんなに %system の割合が大きくはならないかな。
もうちょっと、%user とか %iowait の割合が上がる気がします。
「サーバ再起動」と言ってるのは、OS の再起動ではなく、apache を再起動した、ということでしょうか？
もし、apache の再起動で回復した、ということであれば、20:30 くらいから 21:03 までの accesslog をチェックしましょう。
公開しているサーバであれば、アタックの可能性もあります。
クローズドなネットワークであれば、accesslog から処理を特定して、アプリケーションの処理を確認。
ループしてリクエストを投げてくるようなクライアントアプリとか、無限に子プロセスを作り続けるようなサーバ処理とか。
20:30 くらいから、と書いたのはスワップの空き領域が目立って減り始めた時刻としてなのですが、予兆は 20:10～20:20 くらいからあったのかもしれません。
もし、再起動したのが apache ではなく OS なのだとしたら、原因となったプロセスの特定ができません。
問題が再現したときに、ps コマンドでプロセスの数と、使用メモリサイズを確認して、問題を起こしたプロセスを特定するようにしましょう。
続報です。
/var/log/messagesに何か出てました。
OOM Killer という仕組みがプロセスを殺してます。
メモリが足りなくなってきたときに、殺すとメモリをたくさん解放してくれそうなプロセスを殺してくれます。
何で、irqbalance なんかが殺されなきゃいけないんだろうというのはありますが、20:46:56 に apache が殺されてるので、ここから復旧した、という感じなんでしょうか？
Feb 23 20:46:56 web1 kernel: Out of memory: Killed process 5692 (httpd). Feb 23 20:46:56 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0
/var/log/messages に、↑以降の時間で、同じようなメッセージが出ていなければ、メモリを馬鹿食いしていたプロセスは httpd (apache) に決まりですね。
sar -r の結果だと、20:03:02 で swapfree がゼロなので、もしかしたら他にメモリを食ってたやつがいる可能性があります。
ちょっと子プロセス数が多すぎるのかもしれません。
んー、どうでしょう。
サービスが対象にしている人数というか、トランザクション量と、処理に必要なリソースのバランスだと思うので、一概に多すぎるという印象は無いです。
もし、accesslog で、アタックされているような形跡が無ければ、リソースを食いまくる処理がある（パラメータも含めて）のかも、というところでしょうか。
メモリリソースを食うリクエスト（もしくは、パラメータの組合せ）があるとしたら、Web の利用者は反応が無いと、「もう一度試してみる」というのを何度かやってみる、のはありがちなので、それがリソースの枯渇につながった、という可能性はあります。
どうでも良いことですけど、ook-killer のログ。
init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;
>init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;
普通に考えたら、ダメですよね。。。
No.2
1728320
50pt
サーバを再起動というのは、何時何分のことですか。
21時3分過ぎにApacheを再起動することで、%swpusedが100％以下に徐々に落ちていったように見えます。
そうだとすると、IOの負荷が低いことから、PHPスクリプトが無限ループや無限再帰呼び出しをしてキャッシュを食いつぶしたのではないでしょうか。
php.ini の設定によりけりですが、デフォルトだと /etc/httpd/logs/error_log にエラーログが吐き出されるようになっています。
メモリを食いつぶしているスクリプトがタイムアウトになった場合に、ここにログが残っているはずです。
ありがとうございます。調べてみます。
No.3
1099132
50pt
低負荷なのにCPU使用率が100％？
http://www.atmarkit.co.jp/fjava/rensai2/webopt07/webopt07.html
WEB一般的な話だと、この手の時は、スクリプト（PHP）が無限ループなどを起こしてる可能性があると思います。
php.iniなどの設定で、PHPの実行時間の最大値を短めに設定してみるのはどうでしょうか？
http://php.plus-server.net/function.set-time-limit.html
それでも同じ現象がでて、ログ比較などでスクリプトのループの可能性が低いとなれば
原因はほかにあるかと思います。
スクリプトが無限ループしていても、その発生確率などによって、対策方法は違うかと思います。
ありがとうございます。
続報です。
/var/log/messagesに何か出てました。
https://gist.github.com/DQNEO/5036078
最初に"irqbalance invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0"とありました。
DQNEO
2013/11/18 10:09:22
2
1
1
1
1
2
2
87
73
んー、どうでしょう。
2013/03/01 01:27:39サービスが対象にしている人数というか、トランザクション量と、処理に必要なリソースのバランスだと思うので、一概に多すぎるという印象は無いです。
もし、accesslog で、アタックされているような形跡が無ければ、リソースを食いまくる処理がある（パラメータも含めて）のかも、というところでしょうか。
メモリリソースを食うリクエスト（もしくは、パラメータの組合せ）があるとしたら、Web の利用者は反応が無いと、「もう一度試してみる」というのを何度かやってみる、のはありがちなので、それがリソースの枯渇につながった、という可能性はあります。
どうでも良いことですけど、ook-killer のログ。
init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;
>init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;
2013/03/02 17:36:55普通に考えたら、ダメですよね。。。