DSAS開発者の部屋

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

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

おまけ

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