HTTP リクエスト/レスポンスにかかる時間について

Question

前提

• Docker コンテナ内で python のアプリケーションを動作させています。
• アプリケーションでは複数のスレッドが動いています（5〜10程度）
• requests モジュールを使って HTTP 通信を行っています

発生している問題・エラーメッセージ

以下のようにしてリクエストからレスポンスまでの時間を計測しています。

start = time.time()
response = requests.post(url, files=files, data=data)
elapsed_time = time.time() - start

また、response オブジェクトの elapsed でもリクエストからレスポンスまでの時間を取得できますが、

response.elapsed.total_seconds()

この２つの値の差 (elapsed_time - response.elapsed.total_seconds()) がかなり大きく、またばらつきも大きいのが問題となっています。

具体的には、response.elapsed.total_seconds() の値が 250msec 程度なのに対し、上述の elapsed_time の値はそれより大体 100msec 程度は遅いです（350 msec程度）。
また値のばらつきも大きく、遅いときは 300msec〜500msec 程度遅いですが、早いときは数 10msec 程度だったりします。

response.elapsed はリクエストの最初のバイトを送信してからレスポンスヘッダの解析が終了するまでにかかる時間を測定したものだそうなので、上記の２つに差があること自体はわかるのですが、response.elapsed での測定範囲以外の処理で数百 msec 以上も時間がかかるものでしょうか？

ある程度のリアルタイム性が要求されているシステムなので、この２つの値の差と値のばらつきをできるだけ小さくしたいのですが、どうしていいかわからず途方にくれている状態です。

これが仕方のないものなのか？post メソッドで送るデータに問題があるのか？他のモジュールだと違うのか？他に何か改善する方法があるのか？
など、何か情報をいただければ助かります。

該当のソースコード

リクエストの部分ですが、もう少し詳しく記述すると、以下のような感じです。

data = {}
files = {}
for input in inputs:
    json_data = input['json']
    ret, jpeg_data = cv2.imencode('.jpg', input['image'])
    if not ret:
        continue
    data[input['key']] = json.dumps(json_data), # dict -> str への変換
    files[input['key']] = ("", jpeg_data.tobytes(), 'image/jpeg') # ndarray -> bytes への変換
start = time.time()
response = requests.post(url, files=files, data=data)
elapsed_time = time.time() - start

サーバー側に multipart/form-data で JPEG 画像３枚と JSON を送っています。
input['image'] には OpenCV の VideoCapture で取得したフレームデータ(ndarray型)が入っています。

試したこと

１リクエストでの話なので asyncio とかは関係ないと思いますが、一応 aiohttp モジュールでも試してみました。
しかし状況はほとんど変わりませんでした（若干遅くなったくらい）。
スレッドをやめて全てを asyncio で処理することも試したいですが、変更コストが大きすぎて無理です。

補足情報（FW/ツールのバージョンなど）

• docker 20.10.12
• Ubuntu 20.04
• python 3.8.10
• requests 2.22.0

以上、よろしくお願いいたします。

Comments

[a.‫com]

リダイレクトしてるわけではないですよね？

[kuttsun]

リダイレクトはしていませんが、通信相手はさらに下位のモジュールに HTTP リクエストを送ってはいます。

[a.‫com]

レスポンスbody終了まで時間がかかっているかもしれないので
postではなくてheadにしたらどうでしょう？headだとセッションcloseとconnectionpoolのcloseのみの処理の差ですが
私の環境ではそれでも5msec程度の差がでました。

[kuttsun]

ありがとうございます。
マルチプロセス化したところ、私の環境でも数msecぐらいになりました。
そんなに大きなデータをやりとりしているつもりはありませんが、スレッドが多いことでヘッダーやペイロードなどの解析部分に影響が出ていたのかもしれません。

Answer 1

質問者さんの環境は自分は全く分かりませんので見当外れかもしれませんが、以下ご参考まで。

ASP.NET + IIS では、ASP.NET での計測と IIS のログとに大きな違いが出る場合があります。

理由は:

(1) IIS のログの time-taken には IIS が要求の最初のバイトを受け取ってから、最後のパケットに対するクライアントからの ACK を受け取るまでが含まれる。

(2) ASP.NET での計測は最初のパケットを送信する直前までしか含まれない。

なので、サイズの大きなファイルを遅いネットワークでダウンロードしたりするような場合、time-taken の値と ASP.NET の計測値に大きな差が出ます。実際、time-taken の値が executionTimeout を越えていたという報告もありました。

詳しくは以下の記事を見てください。

IIS ログの time-taken
http://surferonwww.info/BlogEngine/post/2016/07/01/time-taken-of-iis-log.aspx

Comments

[kuttsun]

ありがとうございます。
環境が異なるので今回の件とはまた別かと思いますが、一例として参考になりました。

Answer 2

ばらつきの分布状況がわかりませんが、ホスト名からDNSを引いてIPアドレスを求める時間は、その差の一つでしょうね。キャッシュされるので2度目以降は早い。
あとは、（原典に当たってませんが）「リクエストの最初のバイトを送信してからレスポンスヘッダの解析が終了するまでにかかる時間」が正しいとすると、TCPコネクションを張るのに掛かる時間とか。

あと、リクエストで送っている物が書かれているのに対して、レスポンスの内容が書かれていませんので、おそらくレスポンスは非常に短いと言うことだと思いますが、もし、大きなファイルをレスポンスで返しているならその時間もですね。

Comments

[otn]

同じサイトでも大きなばらつきがあるのか、同じサイトだとばらつきが小さいがサイトが違うと大きいのか、のあたりの分析も手がかりになるでしょう。

[kuttsun]

ありがとうございます。
記載してませんでしたが、通信相手は同一ホスト内で別の Docker コンテナで動いているアプリケーションで、HTTP で API を実行しています。
なので、DNS とかは今回は関係ないかと思います。
また、レスポンス内容は JSON で、データ量はとても小さいので関係ないかなと思っております。

`response.elapsed` についての原典は以下です。

- https://requests.readthedocs.io/en/latest/api/#requests.Response.elapsed

また、以下にセッションを維持する方法がありましたのでこちらを試してみました。

- https://requests.readthedocs.io/en/latest/user/advanced/

結果としては変わらずでした。
ただ、TCP コネクションの維持という観点はなかったので、とても参考になりました。

いろいろ調べてみましたが、単純にスレッドが多いことによる GIL の制限なのかなという気がしてきました。

[otn]

同じLANでしたか。
ホスト名で無くIPアドレスで指定、もしくは、hostsファイルで名前解決と言うことでしょうか？
同じLANだとTCPコネクションの時間のばらつきも小さいはずなので、違いますね。

> いろいろ調べてみましたが、単純にスレッドが多いことによる GIL の制限なのかなという気がしてきました。
CPUバウンドならそういうことでしょうが、Dockerで動いていると言うことでホストリソースの問題もあるかもしれませんね。

[kuttsun]

IP アドレスで指定しております。
そして少し時間がかかってしまいましたが、マルチプロセス化したところ解決しました。
前述した時間差が数百msec あったものが、数msec〜十数msec程度にはなりました。
結果的にはマルチスレッドと GIL の問題で、HTTP は関係ありませんでしたが、こちらをベストアンサーとさせていただきます。
ありがとうございます。