2012年07月06日

ログからは見えてこない高負荷サイトのボトルネック

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

ちょうど1年前に「高負荷サイトのボトルネックを見つけるには」という記事を掲載していますが、この手のトラブルシューティングって結構大変で悩ましいですよね。はじめまして、新入りの@pandax381です。

ログからは見えてこないもの

「サイトの応答が遅い」という問題が発生した場合、その原因はどこにあるでしょうか。

  • Webアプリケーションの処理に時間が掛かっている
  • DBサーバに投げたクエリーの応答が遅い
  • サーバの処理能力を超えている

などなど、いくつもの可能性があります。通常、上に挙げているような問題は、アプリケーションやサーバのログを調査することで、原因を突き止めることができます。

一方で、こういったログの調査だけでは、その原因にたどり着くことができなかったり、相当な苦労が伴うケースもあります。

あるサイトのある日の出来事

つい先日のことですが、KLabの運営している某ソーシャルゲームにて、サイトが重くなるという問題が発生しました。具体的にはHTTPのタイムアウトが頻発していて、クライアントにエラーが返されてしまっているというものです

DSASでは、HTTPサーバがフロント側とバックエンド側の2段構成になっていて、バックエンド側のHTTPサーバが5秒以内に応答を返せない場合、フロント側のHTTPサーバがエラーを返す仕組みになっています。そのため、このケースで真っ先に疑われるのは、バックエンド側のHTTPサーバとそれに紐づくDBサーバやmemcachedサーバです。

各サーバのリソース状態を集約しているリソースモニタを見てみると、確かにバックエンド側のHTTPサーバのレスポンスタイムが大幅に悪化していることがわかりました。こうなると怪しいのはDBサーバです。アクセス集中によってDBサーバが高負荷状態になり、レスポンスに時間が掛かっている可能性があります。

ところが、DBサーバのリソースを確認しても負荷が掛かっているような様子はなく、レスポンスタイムにも問題ありませんでした。同様にmemcachedサーバを確認したところ、こちらもリソース使用率などに問題はありませんでした。

ここで疑いはアプリケーションレイヤからネットワークレイヤへと変わることになります・・・

早速パケットキャプチャ(使うツールは tcpdump ではなく、もちろん miruo です!)してみると、出るわ出るわ、バックエンド側のHTTPサーバからTCPのSYNセグメント再送が大量に発生していました。

SYNセグメントの再送が発生しているということは、TCPの接続に時間が掛かっているということになります。SYNセグメントの再送は、通常 3秒・6秒・12秒・・・という間隔で行われるため、1回目の再送をしてからすぐにSYN/ACKを受け取れればよいのですが、そうでなければ5秒を経過してしまい、フロント側のHTTPサーバから強制切断されてしまいます。

実際にネットワークを流れるパケットを確認して、ようやく原因に一歩近づきました。そして、パケットの情報から対向はmemcachedサーバということもわかりました。

しかし、memcachedサーバは先に確認して問題なかったはず・・・。念のためリソースモニタでもう一度memcachedサーバの状況を確認してみるものの、やはり問題はなさそう。CPUもほどんど使われていないし、トラフィックも100Mbps程度でまだまだ余裕があります。

っと、ここで妙な違和感が。トラフィックのグラフが奇麗に100Mbpsに張り付いているのです。ちなみに、各サーバのNICは全て1000BASE-Tのものが使われています。まさかと思い、memcachedサーバのNICの接続状況を確認するとリンクが100Mになっている・・なぜ?という思いを抱きながら更に調査を進めた結果、今回の問題の原因が判明しました。

memcachedサーバを接続しているスイッチが故障して、そのポートが100Mでリンクされてしまっていたのです。

結局、問題のスイッチを対処してこの問題は解消されましたが、ネットワーク絡みの問題は原因にたどり着くまでに手間が掛かって大変です。

もっと切り分けの手間を減らしたい

上記のようなケースでは、ネットワーク周りの情報、それもTCPレイヤで再送が発生しているかどうかの情報を早い段階で得ていれば、解決までの道のりはずっと容易だったと思います。

実際にはその情報だけでは意味を成さないこともあるでしょうが、その他の情報や起きている現象と照らし合わせて、問題の切り分けや原因を推測するには大いに役立つはずです。

というわけで作りました!

前置きが長くなりましたが、TCPレイヤで発生した再送を検出するプログラムを作りました。

 ・TCPセッションモニタ「tcpeek」

tcpeek(てぃーしーぴーく)は、TCPのセッション確立(3wayハンドシェイク)時に発生するエラーを監視・集計するネットワークモニタです。libpcapを用いたパケットキャプチャ型のプログラムで、tcpdumpなどと同様に監視したいホスト上で起動させるだけで簡単に使えます。

使い方は付属のREADMEを見てください。ちなみに、tcpeekを使うとこんなことができます。

  • エラー検出:RSTやICMPの応答を受け接続に失敗したりタイムアウトしたTCPセッションを集計できます
  • 再送検出:SYNおよびSYN/ACKセグメントの再送が発生したTCPセッションを集計できます
  • フィルタ:通信方向・IPアドレス・ポート番号の組合わせで複数のフィルタが指定でき、フィルタ毎に個別集計できます
  • データ出力:集計したデータをUNIXドメインソケット経由で出力します。スクリプトで扱いやすいJSON形式で出力します
  • gmetric経由でrrdを出力するためのスクリプト(tcpeekstat)が付属しています
  • プロミスキャスモードでも使えます
  • などなど

tcpeekを実行すると、標準エラーへTCPセッションの情報がリアルタイムで出力されます。

$ sudo ./tcpeek -i eth0
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
 TIME(s) |       TIMESTAMP       |      SRC IP:PORT            DST IP:PORT     |      RESULTS      | DUP SYN  DUP S/A
----------------------------------------------------------------------------------------------------------------------
   0.002 | 12-07-06 16:39:02.552 |   192.168.2.227:48967   192.168.2.202:80    |      success      |      0        0 
   0.002 | 12-07-06 16:39:02.559 |   192.168.2.227:48968   192.168.2.202:80    |      success      |      0        0 
   0.002 | 12-07-06 16:39:11.219 |   192.168.2.227:42031   192.168.2.202:443   |      success      |      0        0 
   0.002 | 12-07-06 16:39:11.273 |   192.168.2.227:48970   192.168.2.202:80    |      success      |      0        0 
   0.002 | 12-07-06 16:39:11.279 |   192.168.2.227:42033   192.168.2.202:443   |      success      |      0        0 
   0.002 | 12-07-06 16:39:11.309 |   192.168.2.227:48972   192.168.2.202:80    |      success      |      0        0 
   0.002 | 12-07-06 16:39:11.323 |   192.168.2.227:42035   192.168.2.202:443   |      success      |      0        0 
   0.001 | 12-07-06 16:39:11.354 |   192.168.2.227:42036   192.168.2.202:443   |      success      |      0        0 
   0.002 | 12-07-06 16:39:11.385 |   192.168.2.227:42037   192.168.2.202:443   |      success      |      0        0 
   0.001 | 12-07-06 16:39:36.254 |   192.168.2.228:62876   192.168.2.227:80    | failure (reject)  |      0        0 
   0.000 | 12-07-06 16:39:38.160 |   192.168.2.228:62877   192.168.2.227:80    | failure (reject)  |      0        0 
   0.000 | 12-07-06 16:39:44.689 |   192.168.2.227:56371   192.168.2.228:8080  | failure (reject)  |      0        0
  39.947 | 12-07-06 16:41:29.723 |   192.168.2.227:58376   192.168.2.207:8080  | failure (timeout) |      2        0 
項目説明
TIME(s)TCPセッションの確立(3wayハンドシェイク)に掛かった時間(秒)
TIMESTAMPTCPセッションが開始された時刻
SRC IP:PORTTCPセッションの始端(クライアント)のIPアドレスとポート番号
DST IP:PORT TCPセッションの終端(サーバ)のIPアドレスとポート番号
RESULTSTCPセッションの確立可否
DUP SYNSYNセグメントが再送された回数(再送が発生していなければ 0)
DUP S/ASYN/ACKセグメントが再送された回数(再送が発生していなければ 0)

出力したrrdを元に作成したグラフのイメージです

php

php

おまけ

実は、上で書いているトラブルが起きる前から「TCPの再送検知できると、こういうトラブル起きたときに早く気づけていいよね」という話が出ていました。tcpeekもその頃から作り出していて、ほぼ完成していたのですが、まだ試験中で、本番環境では動かしていなかったのです。そしてこのようなトラブルが実際に起り「tcpeekを動かしていればすぐにわかったのに!」ということになり、早々に本番環境へ投入される流れとなりそうです。


@pandax381
klab_gijutsu2 at 14:50│Comments(2)TrackBack(0)dsas | network

トラックバックURL

この記事へのコメント

1. Posted by pizza   2012年07月07日 19:55
スイッチの監視の方が先だと思います。
ポート障害に気付けないのは、かなりヤバいですよ。
2. Posted by klab_gijutsu2   2012年07月10日 13:44
pizzaさんコメントありがとうございます。
もちろん、それはその通りですよね。
今回のケースでは、サーバにもスイッチにもログは残っていて、アラートメールも飛んできてはいたんですが、完全に見落としてた隙にアプリ側でエラーが多発してアタフタしてしまったというのが事の経緯だったりします。もちろん、アラートを見落としてしまったこと事態反省すべきなのですが、それとは別に、TCPの状態をグラフ化しておくことで、サーバ/ネットワーク管理者以外でも問題の原因に気づくことができて、問題の早期解決に繋がることを期待しています。

この記事にコメントする

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