高負荷サイトのボトルネックを見つけるには
はじめに
アクセスが急増すると、応答時間が著しく悪化するサイトはありませんか?
普段は200ミリ秒以内で安定してアクセスをさばいているのに、イベントやらキャンペーンやらを開始した瞬間から、普段の2倍や3倍のアクセスが殺到し、その結果、レスポンスタイムが3秒とか9秒とかかかるようになってしまうことってありますよね。
あるサイトの実状
つい先日まで、そんなサイトが私の目の前にもありました。自社で運営している某ソーシャル系のサイトなんですが、イベント開始時刻と同時にアクセス数が急増するのです。とはいえ、所詮は普段の2倍とか3倍程度の数なのだから、少なくとも1秒以内にレスポンスを返せるくらいの性能は維持したいものです。
しかし実際は困ったことに、応答に3秒以上もかかってしまう処理が大量に発生してしまう状況に陥ってしまっていました。これはきっと、どこかにボトルネックがあるに違いありません。
仮説を立ててみる
当初は「DBでどっかロック待ちしてるんじゃね?」と、アプリケーションレイヤに原因があると思っていましたが、コードを読み返しても、show statusを叩いても、information_schemaを覗いても、ロックを待っている形跡はみつかりませんでした。
参考記事)
SH2の日記:MySQL InnoDBにおけるロック競合の解析手順
大変解りやすく参考になる記事が多くて、とても助かっています。
この場を借りてお礼申し上げます。
なんでかなあ、なんでかなあ、とApacheのアクセスログを眺めながら頭を抱える日々が続いていましたが、ふとあることに気づきました。
アクセスが増えると、どういうわけか3秒台のレスポンスと9秒台のレスポンスの割合が急増しているのです。3と9って、なんかだよく聞く数字だなあと冷静に考えてみると、これってTCPのSYNの再送間隔ではありませんか!
ということは、WebサーバはDBのロックを待っているわけじゃなくて、どっかのサーバとの接続に時間がかかっている可能性の方が高そうです。
実態を調査する
というわけで、早速tcpdumpで調査・・・をしたくなるのが人情(?)ですが、Webサーバに流れているパケットは膨大な量です。その中から再送パケットを見つけ出すのは、それなりに手間と時間と気力が必要です。しかも、問題が発生するのはイベント時などアクセスが集中する時なので、できればWebサーバにも余計な負荷をかけずにどうにかしたいところです。
というわけで、こんなツールを作ってみました
「みるお」と発音してください。いつもながら変な名前でごめんなさい(><)
miruoの詳細は、また後日紹介させていただくつもりですが、ざっくり言うと「異常と思われるパケットだけを表示してくれる tcpdumpみたいなツール」といったところでしょうか。
問題を切り分ける
Webサーバ上でmiruoを実行してみると、以下のような結果が表示されました。
これは、Webサーバがmemcachedへ接続しにいっている様子ですが、どうやら、SYNが再送されている模様です。つまり、memcachedが、なんらかの理由で新規の接続を受け入れられなくなっているのかもしれません。
原因を追求する
今度は、memcachedサーバに入ってnetstatで状況を確認してみました。
$ netstat -s (------ 略 -----) TcpExt: 96 resets received for embryonic SYN_RECV sockets 19626994 TCP sockets finished time wait in fast timer 621 delayed acks sent Quick ack mode was activated 4268 times 107708 times the listen queue of a socket overflowed 107708 SYNs to LISTEN sockets dropped 97529 packets directly queued to recvmsg prequeue. 22246 bytes directly in process context from backlog 76082834 bytes directly received in process context from prequeue 1761768710 packet headers predicted (------ 略 -----)
なんと、このサーバは接続を受け入れきれずに、SYNを取りこぼしてしまっているみたいです。memcachedのbacklogはデフォルト値を使用しているので1024になっているはずです。
$ memcached -h | grep backlog -b Set the backlog queue limit (default 1024)
これって、本当に1024で足りなくなっているのでしょうか。単純にバックログを増やせば解決する問題かなと期待しつつも、どうも釈然としなかったので 、man listen をじっくりと読み返していたところ、
backlog 引き数が /proc/sys/net/core/somaxconn の値よりも大きければ、backlog の値は暗黙のうちにこの値に切り詰められる。このファイルのデフォルト 値 は128 である。バージョン 2.4.5 以前のカーネルでは、この上限値はコード埋め込みの固定値 SOMAXCONN であり、その値は 128 であった。
いやーな予感がしたので、おもむろにコマンドを叩いてみると・・・・・
# sysctl net.core.somaxconn net.core.somaxconn = 128
あちゃあ!
実際はこれ、128になっていたわけですね!
# sysctl -w net.core.somaxconn=1024
としてmemcachedを再起動したところ、大幅に性能が改善されました。
まとめ
MySQLなどをチューニングする時なども、性能を上げるためにbacklogを値を増やすことは多いと思いますが、net.core.somaxconnの存在を忘れ去っていると、せっかく設定しても高負荷時のアクセスを処理しきれなくなってしまう可能性があります。特に今回のケースだと、平常時は何の問題もでていなかったのでさらに厄介です。
もし、高負荷時にのみ極端に性能が落ちるサーバがあれば、このあたりの設定を確認してみるとよいかもしれません。
トラックバックURL
この記事へのコメント
潰しておかないといけないんですよね。
本番環境で切り分けできることなんてほとんどないので、
後からやると切り分け用の環境を用意するところからやらなければならず、
かなりのコスト増になってしまいます。