Linuxの負荷調査について教えてください。


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

回答の条件
  • 1人5回まで
  • 13歳以上
  • 登録:2013/02/26 14:09:50
  • 終了:2013/03/02 17:39:32
id:DQNEO

質問者から

DQNEO2013/02/26 14:59:38

※レイアウトが崩れて見にくいので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

ベストアンサー

id:a-kuma3 No.1

a-kuma3回答回数4443ベストアンサー獲得回数18252013/02/26 15:49:18

ポイント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 がゼロなので、もしかしたら他にメモリを食ってたやつがいる可能性があります。

他6件のコメントを見る
id:a-kuma3

ちょっと子プロセス数が多すぎるのかもしれません。

んー、どうでしょう。
サービスが対象にしている人数というか、トランザクション量と、処理に必要なリソースのバランスだと思うので、一概に多すぎるという印象は無いです。

もし、accesslog で、アタックされているような形跡が無ければ、リソースを食いまくる処理がある(パラメータも含めて)のかも、というところでしょうか。
メモリリソースを食うリクエスト(もしくは、パラメータの組合せ)があるとしたら、Web の利用者は反応が無いと、「もう一度試してみる」というのを何度かやってみる、のはありがちなので、それがリソースの枯渇につながった、という可能性はあります。


どうでも良いことですけど、ook-killer のログ。
init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;

2013/03/01 01:27:39
id:DQNEO

>init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;

普通に考えたら、ダメですよね。。。

2013/03/02 17:36:55

その他の回答(2件)

id:a-kuma3 No.1

a-kuma3回答回数4443ベストアンサー獲得回数18252013/02/26 15:49:18ここでベストアンサー

ポイント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 がゼロなので、もしかしたら他にメモリを食ってたやつがいる可能性があります。

他6件のコメントを見る
id:a-kuma3

ちょっと子プロセス数が多すぎるのかもしれません。

んー、どうでしょう。
サービスが対象にしている人数というか、トランザクション量と、処理に必要なリソースのバランスだと思うので、一概に多すぎるという印象は無いです。

もし、accesslog で、アタックされているような形跡が無ければ、リソースを食いまくる処理がある(パラメータも含めて)のかも、というところでしょうか。
メモリリソースを食うリクエスト(もしくは、パラメータの組合せ)があるとしたら、Web の利用者は反応が無いと、「もう一度試してみる」というのを何度かやってみる、のはありがちなので、それがリソースの枯渇につながった、という可能性はあります。


どうでも良いことですけど、ook-killer のログ。
init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;

2013/03/01 01:27:39
id:DQNEO

>init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;

普通に考えたら、ダメですよね。。。

2013/03/02 17:36:55
id:oil999 No.2

oil999回答回数1728ベストアンサー獲得回数3202013/02/26 19:52:41

ポイント50pt

サーバを再起動というのは、何時何分のことですか。
21時3分過ぎにApacheを再起動することで、%swpusedが100%以下に徐々に落ちていったように見えます。

そうだとすると、IOの負荷が低いことから、PHPスクリプトが無限ループや無限再帰呼び出しをしてキャッシュを食いつぶしたのではないでしょうか。

他2件のコメントを見る
id:oil999

php.ini の設定によりけりですが、デフォルトだと /etc/httpd/logs/error_log にエラーログが吐き出されるようになっています。
メモリを食いつぶしているスクリプトがタイムアウトになった場合に、ここにログが残っているはずです。

2013/02/27 22:56:08
id:DQNEO

ありがとうございます。調べてみます。

2013/02/28 01:00:25
id:taroe No.3

taroe回答回数1099ベストアンサー獲得回数1322013/02/27 07:02:41

ポイント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

それでも同じ現象がでて、ログ比較などでスクリプトのループの可能性が低いとなれば
原因はほかにあるかと思います。

スクリプトが無限ループしていても、その発生確率などによって、対策方法は違うかと思います。

id:DQNEO

ありがとうございます。

2013/02/27 11:47:33
id:DQNEO

質問者から

DQNEO2013/02/28 14:42:54

続報です。
/var/log/messagesに何か出てました。

https://gist.github.com/DQNEO/5036078

最初に"irqbalance invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0"とありました。

  • id:DQNEO
    事後報告ですが、これはPHP5.1で動いていたPHPスクリプトのメモリリークが原因でした。

この質問への反応(ブックマークコメント)

トラックバック

「あの人に答えてほしい」「この質問はあの人が答えられそう」というときに、回答リクエストを送ってみてましょう。

これ以上回答リクエストを送信することはできません。制限について

絞り込み :
はてなココの「ともだち」を表示します。
回答リクエストを送信したユーザーはいません