Wrk Latency分布不准确的分析
API7.ai
September 3, 2018
wrkは、Redis、NGINX、Node.js、LuaJITといったオープンソースプロジェクトを基盤とした優れたHTTPストレステストツールです。これらのプロジェクトの強みであるイベント駆動、HTTPパース、高性能、柔軟性を活用し、独自のLuaスクリプトを書いてテストリクエストを生成することができます。
wrkにはテストケースがなく、作者が年に一度ほど現れてコードをマージするだけですが、それでもwrkをパフォーマンステストやファジーテストのツールとして使用することを妨げるものではありません。もしまだマルチスレッドのabを使っているのであれば、wrkを試してみる価値は十分にあります。
以下は、wrkの結果から得られた遅延分布の統計部分です。
Latency Distribution
50% 1.20ms
75% 595.78ms
90% 899.11ms
99% 1.00s
この例では、50%のリクエストが1.2msで完了し、90%のリクエストが899msで完了し、99%のリクエストが1秒で完了することを意味します。
私たちが自社製品をwrkでストレステストした際、wrkの遅延統計のほとんどが数ミリ秒以内で完了している一方で、ごく一部のリクエストが100ミリ秒以上の遅延を示していることがわかりました。OpenRestyで構築されたシステムにとって、これほどの遅延が発生することは科学的ではありません。
この問題の最終的な解決策は非常にシンプルでしたが、具体的な分析と問題の特定には少し時間がかかり、数日を要しました。最終的な解決策自体は重要ではなく、問題に対するプロセスと思考方法が興味深い点です。
遅延問題に遭遇したとき、私たちの最初の反応は、コードやシステムのどこかでブロッキングが発生しているのではないかというものです。システムが複雑であるため、フレームグラフを提供します。
この種の問題を分析するための既存のsystemtapスクリプトは存在しないため、スクリプトを書くのに少し時間がかかりました。しかし、systemtapスクリプトを何度か調整しても、大きな遅延は捕捉されず、これはwrkの結果と明らかに一致しませんでした。スクリプトが完璧ではなく、フックされていない関数を見逃している可能性があると推測しましたが、同時にwrkの結果の正確性にも疑問を抱きました。
そこで、wrkの統計が間違っているのか、それともサーバー側に問題があるのかを特定しようと試みました。wrkが実行されているサーバーでクラッシュテストのパケットをすべてダンプし、時間順に並べ替えたところ、wrkの遅延統計とは大きく異なり、100ミリ秒を超えるリクエストはありませんでした。このテストを何度か繰り返しても、結果は一貫していました。
これで目標が明確になりました。wrkの遅延統計に関するコードをスムーズに修正することです。最も懸念されるのは、wrkの内部統計にバグがあることで、これは修正が容易ではありません。なぜなら、テストケースが一切ないプロジェクトだからです。
wrkの統計ロジックを確認し、開始時と終了時にログを追加したところ、遅延に関する統計が正しいことがわかり、安心しました。しかし、最終結果を出力する前に、statistic correctionというコードが存在します。
if (complete / cfg.connections > 0) {
int64_t interval = runtime_us / (complete / cfg.connections);
stats_correct(statistics.latency, interval);
}
このif文によると、圧力データが生成されるたびに修正が行われます。興味があれば、stats_correct関数のコードを見てみてください。たった10行ですが、何度読んでも理解できませんでした。
コードのコミット記録を再度確認すると、以下のような記述がありましたが、理解できませんでした。
remove calibration & improve CO correction
ここで少し愚痴を言わせてもらうと、コミット記録がもう少し詳細で、省略せず、コードコメントを追加していれば、多くの手間を省けたでしょう。
問題はここまで確認され、製品の問題ではないことが確認されました。解決策はすでにあり、上記の修正コードをコメントアウトすることです。しかし、wrkの作者が意図的にこれを追加した理由があり、その理由を理解しないままでは潜在的な問題が残ります。当然、作者にissueを開いて質問しました。年に一度現れるwgが15日後に返信し、上記のコミット情報の略語COがCoordinated Omissionを指していることを教えてくれました。この問題に特化した記事も紹介されました。興味のある方はこのキーワードで検索してみてください。
簡単に言うと、Coordinated Omissionとは、ストレステストを行う際に、送信から応答までの時間だけを計測するのは不十分であり、これはservice timeを指します。これでは多くの潜在的な問題を見逃してしまいます。テストリクエストの待ち時間も計測する必要があり、これがユーザーが気にするresponse timeとなります。
CO問題を提唱したGil Teneは、wrkにCO問題に対処するための修正を加えました: https://github.com/giltene/wrk2。このプロジェクトのREADMEにはいくつかの説明がありますので、興味があれば読んでみてください。ここでは詳しく触れません。
私たちの製品では、コード内にブロッキングはなく、ストレステストを行う際にはCPUをフル稼働させています。ブロッキングがあっても、フレームグラフでサンプリングして分析できます。したがって、wrkがここで行っているCoordinated Omissionに対する単純で粗暴な修正は、むしろ誤解を招くものです。