突然サーバーが遅い・繋がらないといった障害に遭遇した時のトラブルシューティング（TCP Send-Q/Recv-Qまわり）

植木和樹

2018.12.27

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

はじめに

こんにちは植木和樹＠上越オフィスです。本日はTCPネットワークのトラブルシューティングの備忘録です。

先日、本社サーバー室にあったSOCKSプロキシー(delegated)をAWS EC2に移行しました。EC2環境は3ヶ月前から並行運用を開始しており問題なく稼働していましたが、本社プロキシーを停止し全面的にEC2プロキシーに切り替えたところ「ネットに繋がらない」「遅い」という苦情が社内からあがりました。

本日はその時の対応、原因調査、対策の経緯を残しておきたいと思います。

最初に結論を書いておくと、net.core.somaxconnやdelegatedプロセスの同時接続数設定の話です。これまでこの辺の話は何度も何度も何度も何度も、調べて読んで理解していたつもりでしたが、数年経つとすぐに忘れてしまうため数年後に自分がまた見返せるようにまとめておきたいと思います。

発生の経緯

時系列での経緯

11月のビルメンテナンスに合わせて本社サーバー室のプロキシーをEC2に切り替える準備を進める
10月29日本社プロキシー動作不良（最終的な原因は不明）
同 9:30 DNSレコードを変更しプロキシーの向き先をEC2に
同 11:40 プロキシーが遅い、繋がらないという苦情が社内から出始める
同 12:30 プロキシーサーバーのスペックを t3.micro から t3.small にあげる
11月7日遅い・繋がらないが再発（一部の利用者が大量のデータ送信を行っていた）
11月14日遅い・繋がらないが再発（一時的なもの）
11月15日 Gangliaを導入してTCP周りの詳細モニタリング開始
11月16日 Delegateのlistenerおよびprocess数の調整を実施
11月20日恒久対策の効果を確認し対応終了

環境

$ cat /etc/system-release
Amazon Linux AMI release 2018.03

$ uname -r
4.14.42-52.37.amzn1.x86_64

暫定対応

Delegateプロセスの再起動（発生時は SYN_RECEIVED 状態のプロセスが大量にあるため）

効果がなかった対応

EC2のスペックを t3.micro → t3.small にあげる → 効果なし
カーネルパラメータ net.core.somaxconn, net.ipv4.tcp_max_syn_backlog をいじる
カーネルパラメータ net.ipv4.tcp_tw_reuse をオンにする

恒久対策

Delegateの起動パラメーターを調整

MAXIMA=delegated:256
MAXIMA=listen:128

参考：はじめてのDeleGate (DeleGate導入の手引きver.9用)

原因調査

切り替え当日〜11月初旬

利用者数が少ないと問題なく、ある時間帯だけ遅くなる。ブラウザをリロードすると表示されるまでに待ちが発生するかタイムアウトする。という状況から次の原因を考えた。

単純にスペックが足りてない
どこかに問い合わせ（名前解決等）に行っていてタイムアウトしてる
待ち行列に入ってタイムアウトしてる

SOCKSプロキシーが接続先ホストの名前解決に時間かかってるのかな？とも思ったが、プロキシーと同じサブネットにあるEC2で症状はでていないため調査優先度を下げる。

今回はなにかしら待ち行列に入ってるんだろうと仮定し、ネットワークまわりの記事を参考に原因箇所を調査した。

参考にした記事

調査方法

プロキシーサーバーにログインして、screen コマンド等で複数セッションを起動、それぞれで次のコマンドを実行する。

1) backlogのオーバーフロー発生回数の確認

watch "netstat -s | grep -i listen"

190655 times the listen queue of a socket overflowed
190655 SYNs to LISTEN sockets ignored

発端はこの数値の上昇。接続が遅い、繋がらない時にはこの値が上昇していた。

2) TCPのステータス別合計

watch -d 'netstat -nt|awk "/^tcp/{print \$6}"|sort |uniq -c'

   25 ESTABLISHED
    5 TIME_WAIT

接続が遅い、繋がらない時にはSYN_RECEIVED が大量に発生していた。つまりサーバーがSYN/ACKを送れていないか、ACKを受け取れていない。

3) TCPのbacklogサイズの確認【重要】

SOCKSのポート 1080 番で絞り込む。

watch -d "ss -ant '( sport = 1080 )' | grep -v ESTAB"

State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
LISTEN     0      128          *:1080                     *:*

参考：linux【ss/netstat】コマンドの見方/オプション～Recv-Q/Send-Qやポート確認(Listen/Estab/Unconn),プロセス表示等～ | SEの道標

Send-Q は受け入れ可能な最大TCPコネクション未確立通信の数。ここの数値が小さすぎると、クライアントからの接続要求を受けきれず「遅い・繋がらない」状況になる。

Delegateでは当初ここの値が20だった。少ない。

ブラウザでプロキシーを指定した場合、ページ読み込み時には小さく大量な接続が確立されるはずなので20だと全然足りないはず。

4) Delegateのプロセス数の確認【重要】

watch "ps -ef|grep DeleGate | grep -v grep|wc -l"

10

上記Send-Qの値を増やしても、キューに溜まった接続要求をさばくプロセスが少ないと「遅い・繋がらない」状況になる。

Delegateでは当初ここの値が128だった。

11月14日モニタリング開始

調査の結果listenoverflowsが発生していると考えモニタリングを開始。簡単に導入でき、すぐに値の収集と可視化ができる点でGangliaを導入し様子をみる。

Amazon LinuxにGangliaをインストールしてnetstatの値をモニタリングする

恒久対策

Delegateの起動パラメーターを調整し、キューのサイズと同時実行プロセス数を増やす。

MAXIMA=delegated:256
MAXIMA=listen:128

当初listenだけ20→128に増やしたが、今度はssコマンドでRecv-Qが増加した。つまりaccept待ちのキューが増えたということなのでプロセス数を増やした。

結果、11月20日（月）を最後にlistenoverflowsは発生しなくなった。

カーネルパラメーターに関する補足

ちなみにnet.core.somaxconnはlistenを増やしすぎないためにOS側で設けている上限なので、これだけいくら増やしても意味がない。

さらにいうとキューは2段構えになっていて、それぞれ下記のカーネルパラメータが対応する。

TCP 3ウェイハンドシェイク中のキュー（接続未確立） ... net.ipv4.tcp_max_syn_backlog
accept待ちのキュー（接続確立済） ... net.core.somaxconn

が、通常この2つのパラメータは同じ値にしておくのが良さそう。

まとめ

分かってたようで分かってない知識で、原因の特定と解決に時間がかかってしまいました。

今回の原因調査と対応の流れを簡単にまとめます。

netstat -s | grep -i listen でオーバーフローが起きていないか確認する。
ss -ant '( sport = 1080 )' | grep -v ESTAB のSend-Qの値をみてBacklogサイズは十分にあるか確認する。
Backlogサイズが十分になければ、プロセスのLISTEN数を増やす。
LISTEN数を増やしても一定数増えなければ net.core.somaxconnとnet.ipv4.tcp_max_syn_backlog を増やす。
ss -ant '( sport = 1080 )' | grep -v ESTAB のRecv-Qの値をみてacceptが間に合っているか確認する。
ps -ef | grep DeleGate | grep -v grep|wc -lでプロセスが上限に達していないか確認する。
acceptが間に合ってなくて、プロセス数が不足していれば同時実行プロセス数を増やす。
acceptが間に合ってなくて、プロセス数が十分であれば性能不足。マシンのスペックをあげる。