どうも、もち256です。

最近Mac Book Airを購入し、試しに自作のパフォーマンス検証ツールを動かしたところ、TCP通信におけるTIME_WAITが原因でハマってしまったので、ブログに書いておきます。

ちなみに購入したMac Book Airは下記のもので、CPU8コア、GPU8コア、16GBのRAMでSSD 512GBのというスペックになっています。

事の発端

冒頭にも書いたのですが、まずは新しく購入したMacで自作のパフォーマンス検証ツールを動かすことにしました。

まずは下記コマンドでサーバを起動しました。

APP_SERVER_PORT=8000 APP_COUNT_MAX=50000 ./server.py

そして、このサーバからジョブを受け取って処理を行うクライアントを起動しました。

APP_URL="http://localhost:8000" ./client.py

すると、MacのCPU負荷に不可解な点が発生しました。
MacのCPUの負荷が高くなった後、急激に減少する現象が起こっています。

また5並列でツールを動かした際も「5万件の処理が100秒台で完了する」など、処理速度がラズパイの5並列で実行した場合と同じ結果になり、この部分も少しおかしいと思いました。

（Macの方がラズパイよりも遥かにスペックが高いため、同じ5並列ならばMacの方が速くなるのではないかと）

原因を調べてみる

スレッド数を調べる

まずはtopコマンドでサーバ実行時のスレッド数を調べてみます。

もしかしたら、サーバから生成されるスレッドが多すぎるがゆえ、処理に制限がかかっていたのではないかと考えていました。

top -pid `ps -ef | grep server.py | grep -v 'grep' | awk '{print $2}'`

以下が結果です。

スレッドは終始2個しか実行されていなかったので、スレッドが原因ではなかったようです。

Processes: 454 total, 2 running, 452 sleeping, 1705 threads                                       15:45:19

#（省略）

PID   COMMAND      %CPU TIME     #TH  #WQ  #POR MEM  PURG CMPR PGRP PPID STATE    BOOSTS    %CPU_ME
1361  python3.9    0.0  00:07.34 2    0    24   11M  0B   0B   1361 1022 sleeping *0[1]     0.00000

言語・フレームワークを変えてみる

pythonか、pythonで使用している「http.server」が原因なのかと考え、サーバアプリをRustで書き換えたうえHTTPの通信をやめて、純粋なTCPの通信で計測をすることにしました。

• performance_tester

ただ、こちらでも改善が見られないため、恐らくTCP通信による、何かしらの仕様によるものだと考えました。

TIME_WAITが原因だった

TCPの仕様が原因であると仮定して、安直に「massive tcp connection not work」とググりました。

そこで、Microsoftの下記のページが出てきました。

In a situation where you suspect port exhaustion, an application or process won't be able to release all the ports that it has consumed and will remain in the TIME_WAIT state. Microsoft: Troubleshoot port exhaustion issues

「ポートの枯渇」そういうのもあるのか...

TCP通信がTIME_WAITな状態になる、というのは通信を終了する際、別のプロセスが同一のポート番号を利用しないようにする仕様らしいです。
（もしネットワーク上で遅れてパケットが届いた際、新しく起動されたプロセスに古いプロセスへ送られたパケットが届かないようにする仕組みらしい。）

とりあえず、大量のコネクションがTIME_WAITな状態であると通信ができないとのことで、CPU負荷が極端に下がった時のTIME_WAITの状態を調べてみました。

netstat -an|ggrep -oP "^tcp4.+TIME_WAIT"|wc -l
# output: 16377

結果、（Mac Book Airだと）TCPコネクションが1.6万程TIME_WAITの状態になると、そのプロセスで起動されているアプリケーションと通信ができなくなることがわかりました。

検証ツールの仕様を変更して解決した

TCP通信を行なって大量のTIME_WAITが発生することによって通信が行えなくなってしまうということがわかったので、検証ツールを以下の仕様に変更しました。

改修前: 通信1回ごとにジョブを1つ渡す
改修後: 通信1回ごとに渡すジョブの数を任意で設定できる

改修後の測定ツールは下記リポジトリにコミットしてあります。

• v1.0: performance_tester

この仕様で、素数判定する値の範囲を1〜500万、一度に渡すジョブの数を1万毎にしたところ、下記のようにCPU使用率が急落する現象が解決できました。

おわりに

ということで、TCPのTIME_WAITの問題で苦労したので、みなさんお気をつけください。

あとは、以前に改修前の測定ツールでk8sのジョブ実行のパフォーマンス検証を行なってしまっているので、こちらは後ほど再検証の必要がありますね。

（改修前のツールではTIME_WAITが原因で1秒あたり500リクエストしか受け付けられなかったため、最速でも5万リクエストを100秒でしか処理できず、処理速度が頭打ちになっていた可能性もあるので）

ここまで読んでいただき、ありがとうございました！