1. 背景
身もふたもないことを言えば、そもそもホストからHTTPリクエストが送信されるタイミングを厳密に計測する必要はないかもしれません。単に「１つのHTTPリクエストが送信されたタイミングをどれくらい正確に計測できるのか？」ということが興味深く思ったため、さまざまなレイヤで計測する方法を調べてみました。
2. 方法
アプリケーションからHTTPリクエストを実際に送信するためには、以下のような経路を辿ることになります。
この中で、計測できるステップとして存在するのは
- アプリケーション内部のログ
- アプリケーションからのsyscall (write(), send() など）
- NICへの伝達（tcpdump）
が存在します。
3. 各層でのキャプチャ
アプリケーション内部
メリット
- 最も気軽で簡単
- オーバーヘッドが比較的小さい
- 1つのHTTPリクエストの送信時刻を確実にキャプチャできる
デメリット
- 精度がかなり低い場合がある
まず、アプリケーション内のログは送信タイミングとして全く信用に足りません。例えばPythonのHTTPの非同期送信でいえば、
session = FuturesSession(executor=ProcessPoolExecutor(max_workers=os.cpu_count())
future = session.post(...)
send_time = time.time()
logger.info(f"[INFO] send_time: {send_time}")
のようにアプリケーション層でログを出力しようとしても、実際にこのsend_timeのタイムスタンプが押されるタイミングではsyscallすら呼ばれていません。FutureSessionの実装的には、futureを即時返却し、制御をメインスレッドに返します。従って、send_timeのタイムスタンプは実際の送信よりもかなり前になってしまいます。少し極端なパターンですが、実際にこのコードを含むアプリケーションを高スループットで実行したとき、ログのタイムスタンプとエンドポイントのリクエスト受信時刻には数分の差があった場合もありました。
もしアプリケーション層のみで計測したければ、ここで使われているライブラリにロガーを仕込むこともできますが、さまざまなメソッド全てに対してこれを行うのは面倒だしあまり現実的ではありません。このためおそらく「もっと下の層でキャプチャできないか？」と思うのが自然な流れです。
一方で、これよりも下の層に行くと「1つのHTTPリクエストの送信」と「1つの関数実行」のようなものが完全に一対一で対応する保証がなくなります。その観点で、最も気軽な妥協点がアプリケーション内のログによる計測になるのもまた自然です。
システムコール
メリット
- アプリケーションログより圧倒的に精度が高い
デメリット
- 設定が少し面倒な場合がある
- アプリケーション上の1つのHTTPリクエストと、それに対応するシステムコールを完全に対応づけるのが条件によっては困難
アプリケーション内のログは、送信メソッドの直後にロガーを呼んでもそれがリクエストの送信タイミングに比べてどれくらいずれるかは完全に実装次第です。したがって、アプリケーションの言語にもよりますし、言語が同じでもどのクライアントを使うかにも依存します。一方で、システムコールが呼ばれたタイミングでは、少なくともアプリケーション層の責務を離れ、OSのスケジューラに登録されるタイミングであることは保証されます。言い換えれば、システムコールが呼ばれたタイミングと実際のリクエスト送信タイミングのずれは、アプリケーションには依存しません。
一方で、システムコールを追跡するためには
- strace
- perf
- eBPF
などのコマンドやツールを使う必要があります。strace, perfはコマンドラインから簡単に使えるツールです。straceはPIDを指定するなどして、特定のプロセスから呼ばれたsyscallに絞ってトレースできるため、動的で便利ですが、そのプロセスからsyscallが呼ばれた場合、必ずインターセプトが起こり、オーバーヘッドが大きくなります。低負荷ではあまり問題はないですが、高負荷状態ではstraceの影響が無視できなくなります。perfはstraceと比べれば軽量ですが、統計情報を得ることに主眼があるため、perfからでは1つ1つのsyscallを追跡することはできません。
eBPFはカーネルに動的にコードを挿入し、そこを起点に記録する方法です。インターセプトが起こらない点でstraceよりもオーバーヘッドは小さくなりますが、それでも高負荷になれば避けられないパフォーマンス低下は起こります。
しかしながら、システムコールの呼び出し履歴を持っていても、それをアプリケーション層での1つのリクエストと対応させるのは困難な場合があります。これは、1回のHTTPリクエスト送信が複数のsyscallに分割される可能性があるためです。
前述のPythonのライブラリでは、小さいボディのリクエストに対してsyscallが分割されるという挙動はありませんでした。しかし、そうでない実装も存在し、例えばGoのhttpではかなり頻繁に分割を行い、リクエスト1つに対して平均的に3つ程度のsyscallが観測されました。もしすべてのリクエストが別のソケットから送信される場合、PIDによって追跡可能ですが、ソケットのkeep-aliveを使っていた場合は、事実上1対1で完璧にマッチさせる静的アルゴリズムはないように思います（※1）。このため、システムコールを使用した追跡は完全性を失うという不可避的なデメリットがあります。
（※1）HTTPの場合はリクエストボディが平文になるので、これらをキャプチャすることで比較的簡単に対応させられます。一方、HTTPSの場合は復号しなければいけないので、この方法は現実的ではありません。
ネットワークインターフェース
メリット
- ローカルホスト内では最大の精度
デメリット
- システムコール同様、1つのHTTPリクエストと、それに対応するパケットをマッチさせるのが困難
tcpdumpなどを使って、NICに渡される直前のパケット情報を取得することで、syscallよりもよりホストからの実送信時刻に近いタイムスタンプを得ることができます。これは、仕組みとして、syscallによってTCP送信バッファに情報が書き出され、それがNICに渡されることでネットワークに情報を送信しているためです。
ただし、NICにデータが渡されてもそれが即時送信されるわけでないので、tcpdumpのタイムスタンプも実送信時刻とは小さいながらもズレがあります。また、syscall同様、１リクエストを1つのパケットで送信するかもわからないので、HTTPリクエストとの対応関係も不明です。
（Appendix) NICのハードウェアタイムスタンプ
ハードウェアタイムスタンプ対応のNICに限って、完全に正確な時刻を得ることもできます。しかし、このような環境はあまり一般的ではないです。例えばAWSのEC2でも、いくつかのリージョンでしかハードウェアタイムスタンプ機能が有効なNICを持つVMを提供していません。将来的に、PTPがより一般的になる中で多くのNICがハードウェアタイムスタンプに対応するようになれば、よりこの方法の実用性が増すかもしれません。
4. まとめ
- HTTPリクエストの送信タイミングは、いくつかの層でキャプチャする方法が与えられている
- 最も正確なのはハードウェアタイムスタンプだがあまり普及しておらず実用性が低い
- 最も気軽なのはアプリケーション内のログだが、かなり正確性が低い場合がある
- syscall, tcpdumpの情報を使えばアプリケーションログよりかなり高精度の計測が可能だが、HTTPリクエストとsyscall, パケット情報を一対一で対応させるのは難しい