人力検索はてな
モバイル版を表示しています。PC版はこちら
i-mobile

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


●質問者: DQNEO
●カテゴリ:ウェブ制作
○ 状態 :終了
└ 回答数 : 3/3件

▽最新の回答へ

質問者から

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


1 ● a-kuma3
●100ポイント ベストアンサー

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


DQNEOさんのコメント
回答ありがとうございます。 > もうちょっと、%user とか %iowait の割合が上がる気がします。 そうなんです。%systemだけが上昇するという現象は初めてみたので、何だろうと思いました。 「サーバ再起動」は私の勘違いで、正しくは「自然解消」でした。失礼しました。

a-kuma3さんのコメント
自然復旧だと、アプリの無限ループは考えにくいかなあ... 少なくとも、単純なループだと %user が跳ね上がるはずだし、ワーカープロセスがループした場合、クライアントには timeout が返っても、ワーカープロセスはループしたままのはずだし(思い違いかも)。 メモリ獲得が主な処理で、swap が memfs や、SSD な領域に割り当てられていると、こういう感じになる可能性はあるかもしれません。 swap を食いつぶし、メモリ獲得がエラーを返してワーカープロセスのループが終了する、とか。 にしても、php のアプリでは、ちょっと考えにくい。 accesslog で、怪しい(アタック、というだけではなく、処理時間とかも)ログが残ってなければ、apache 関連以外のプロセスの可能性も。 # 憶測ばっかりで、あまり参考になりませんね <tt>X-(</tt>

DQNEOさんのコメント
ありがとうございます。accesslog調べてみます。

a-kuma3さんのコメント
syslog (oom-killer) のこと、ちょっとだけ追記しました。

DQNEOさんのコメント
ありがとうございます。 Apacheがメモリをたくさん使っていたのは事実です。(Webサーバなので、むしろApacheくらいしか動かしてない) 他のoom killerの餌食になったやつを調べてみました。 <pre> $ sudo grep oom /var/log/messages.1 Feb 23 20:46:56 web1 kernel: irqbalance invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 20:46:56 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 20:49:40 web1 kernel: init invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:03:02 web1 kernel: automount invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:03:05 web1 kernel: snmpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:03:05 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:03:06 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:03:06 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:03:07 web1 kernel: master invoked oom-killer: gfp_mask=0x200d2, order=0, oomkilladj=0 Feb 23 21:10:21 web1 kernel: syslogd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 Feb 23 21:14:12 web1 kernel: httpd invoked oom-killer: gfp_mask=0x201d2, order=0, oomkilladj=0 </pre>

DQNEOさんのコメント
ちなみにApacheの設定はこんなんです。ちょっと子プロセス数が多すぎるのかもしれません。 <pre> # prefork MPM <IfModule prefork.c> StartServers 70 MinSpareServers 70 MaxSpareServers 70 ServerLimit 70 MaxClients 70 MaxRequestsPerChild 400 </IfModule> </pre>

a-kuma3さんのコメント
>> ちょっと子プロセス数が多すぎるのかもしれません。 << んー、どうでしょう。 サービスが対象にしている人数というか、トランザクション量と、処理に必要なリソースのバランスだと思うので、一概に多すぎるという印象は無いです。 もし、accesslog で、アタックされているような形跡が無ければ、リソースを食いまくる処理がある(パラメータも含めて)のかも、というところでしょうか。 メモリリソースを食うリクエスト(もしくは、パラメータの組合せ)があるとしたら、Web の利用者は反応が無いと、「もう一度試してみる」というのを何度かやってみる、のはありがちなので、それがリソースの枯渇につながった、という可能性はあります。 どうでも良いことですけど、ook-killer のログ。 init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^;

DQNEOさんのコメント
>init とか、automount とか、syslogd って、止めても良いんでしたっけ (^^; 普通に考えたら、ダメですよね。。。

2 ● oil999
●50ポイント

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

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


DQNEOさんのコメント
「サーバ再起動」は私の勘違いで、正しくは「自然解消」でした。失礼しました。

DQNEOさんのコメント
無限ループや無限再起でメモリ食いつぶした説ですか、なるほど。 その辺を疑ってみます。

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

DQNEOさんのコメント
ありがとうございます。調べてみます。

3 ● taroe
●50ポイント

低負荷なのに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

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

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


DQNEOさんのコメント
ありがとうございます。

質問者から

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

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

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


関連質問

●質問をもっと探す●



0.人力検索はてなトップ
8.このページを友達に紹介
9.このページの先頭へ
対応機種一覧
お問い合わせ
ヘルプ/お知らせ
ログイン
無料ユーザー登録
はてなトップ