Kubernetes 1.17でflannel起因でレスポンスタイムが律速になったので解決した
先日ペパボのあるサービスでKubernetes1.12系から1.17系に更新した際にflannelに起因したパフォーマンス問題が発生したので紹介します。
なお、本事象はGitHubのIssue上に情報がありますが、日本語話者の情報はあまりないので記事に書くことにしました。
余談を最後に書くと、1.12系から、1.17系のウルトラジャンプがなせたのは、AWSとオンプレミスOpenStackなハイブリッドクラウド環境なので、クラウドをまたいだBG運用ができるからこそなせる技だと思います。それでは本題になります。
1.12のときと比較して全体的にレスポンスタイムが遅い
事象として、1.17にバージョンを上げた直後から、WEBサーバのレスポンスが全体的に1.5～2倍程度遅くなったという事象が発生しました。
その際に調査として下記のようにcurlの出力を変更して調査したところ、接続処理が遅いということがわかりました。
# cat time-format.txt
time_namelookup: %{time_namelookup}s\n
time_connect: %{time_connect}s\n
time_appconnect: %{time_appconnect}s\n
time_pretransfer: %{time_pretransfer}s\n
time_redirect: %{time_redirect}s\n
time_starttransfer: %{time_starttransfer}s\n
----------\n
time_total: %{time_total}s\n
curl -I -w @time-format.txt -s 10.240.0.125:xxxx/example -H "Host:api.example.com"
...
time_namelookup: 0.000s
time_connect: 3.002s
time_appconnect: 0.000s
time_pretransfer: 3.002s
time_redirect: 0.000s
time_starttransfer: 3.349s
----------
time_total: 3.349s
3.349秒のうち、time_connectが3.002秒なので、接続処理が支配的というのがわかります。
次にKubernetesでflannelを利用している場合、NATを利用して通信されるため、接続にあたりを付けるために、conntrack tableを覗いていきます。
# conntrack -L -n|grep 31576 |&grep -v TIME_WAIT
conntrack v1.4.3 (conntrack-tools): 2922 flow entries have been shown.
tcp 6 118 SYN_SENT src=10.240.0.125 dst=10.240.0.125 sport=40112 dport=31576 [UNREPLIED] src=10.233.86.51 dst=10.233.79.0 sport=80 dport=15474 mark=0 use=1
このとき、何度かコマンドを実行していると SYN_SENT でしばらく表示されるレコードがあることに気づきました。ここまで絞れると、お得意の古代兵器である程度原因を特定することができます。
~# tcpdump -i flannel.1 dst port 80 and src host 10.233.79.0
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on flannel.1, link-type EN10MB (Ethernet), capture size 262144 bytes
17:01:03.483430 IP 10.233.79.0.10024 > 10.233.71.50.http: Flags [S], seq 2340116947, win 43690, options [mss 65495,sackOK,TS val 151530136 ecr 0,nop,wscale 7], length 0
17:01:04.481397 IP 10.233.79.0.10024 > 10.233.71.50.http: Flags [S], seq 2340116947, win 43690, options [mss 65495,sackOK,TS val 151530386 ecr 0,nop,wscale 7], length 0
17:01:06.485388 IP 10.233.79.0.10024 > 10.233.71.50.http: Flags [S], seq 2340116947, win 43690, options [mss 65495,sackOK,TS val 151530887 ecr 0,nop,wscale 7], length 0
flannelのインターフェースを覗いていると、Synパケットを再送している処理を確認することができました。これで何かしらの問題が発生して、Synパケットが到達できていないという事象が特定できたのであとはおもむろに「Kubernetes 1.17 flannel syn」とかでGitHubのIssueを探してみます。
Issueではflannelを利用しているかつ、処理が低速である場合にSynパケットが再送され、かつ、その2パケット目がiptablesでマークされないことからこの事象が発生すると述べられており、対応方法としてはnicのTCP Offloadを無効にすることが挙げられていました。要はnicでのパケット分割をやめてカーネルでやるということです。
この事象以外でもTCP Offloadは度々踏み抜くことがあり、またお前か・・・という気持ちになりましたが、下記で無事解決。
# ethtool --offload flannel.1 rx off tx off
ピークタイムにおいてレスポンスタイムが律速になる
前述の問題を解決してめでたしめでたしと思っておったところ、次はサービスのピークタイムにおいて、レスポンスタイムが律速になるという問題が発生しました。ピークタイムということからアクセス数もしくはコネクション数に起因する問題というのはすぐに経験から想定できたので、contrack周りを調べましたが、特にコネクション数がシステム上限を超えているような状況ではありませんでした。しかし、ワークアラウンドとしてサービスの受け口となるKubernetesのIngressを増やしたところ症状が良化したたため、なにかネットワーク周りの問題であることは間違いなさそうということだけがわかっていました。
何か類似の事象があるはずと思い、GitHubのIssueを探していると下記のIssueを見つけました。
また上記から参照されているIssueは下記です。
これらは端的にはLinuxにおいてiptablesがポート採番でレースコンディションになり、パフォーマンスが低下するのを避けるために、iptablesのオプションとして --random-fully を採用するというものです。
このフラグについては下記ページが詳しいです。
対応としては我々が利用していたKernelではiptablesのバージョンが低く、上記のフラグを利用できなかったため、Kernelとディストリビューションを変更することで根本的な対応を行いました。
まとめ
今回起きたものは割とKubernetesというよりかはLinuxのレイヤーに関連するもので、やはりKubernetesが導入されて楽になった部分はあれど、パフォーマンスの問題が起きたときに解決するためには古代兵器を活用できることや、Linuxカーネルに対する理解などが必要になるなぁと思いました。一方で、Kubernetesに対する理解がないと解決できないのも事実なので、自分の得意な領域で慢心することなく、どんどん知識を増やしていかねばなぁとおもたので、Pythonと機械学習の本を買ったのが今です。それでは、皆様良い週末をお過ごしください。
