2011年07月08日

高負荷サイトのボトルネックを見つけるには

はてなブックマークに登録

はじめに

アクセスが急増すると、応答時間が著しく悪化するサイトはありませんか?
普段は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を実行してみると、以下のような結果が表示されました。

miruo0

これは、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の存在を忘れ去っていると、せっかく設定しても高負荷時のアクセスを処理しきれなくなってしまう可能性があります。特に今回のケースだと、平常時は何の問題もでていなかったのでさらに厄介です。

もし、高負荷時にのみ極端に性能が落ちるサーバがあれば、このあたりの設定を確認してみるとよいかもしれません。

klab_gijutsu2 at 14:22│Comments(2)TrackBack(0)network 

トラックバックURL

この記事へのコメント

1. Posted by pizza   2011年07月09日 08:45
本当はサービス開始前の性能試験で
潰しておかないといけないんですよね。
本番環境で切り分けできることなんてほとんどないので、
後からやると切り分け用の環境を用意するところからやらなければならず、
かなりのコスト増になってしまいます。
2. Posted by なおき   2011年07月12日 19:13
うーん、このレベルまでの切り分けや性能試験ができるようになりたいなぁ。

この記事にコメントする

名前:
URL:
  情報を記憶: 評価: 顔   
 
 
 
Blog内検索
Archives
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
最新コメント