nginxのrequest_timeにはSSL Handshakeにかかった時間は入らないっぽい

$request_time
request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client

nginxはrequest_timeをログに出すことで処理時間がどれくらいかかったがわかる。処理時間ってどこからどこまでだろうをドキュメントを見るとクライアントから最初のバイトが来た時間から最後のバイトがクライアントに送信されてからログに書き込まれるまでの経過時間。ってなっている。SSLを使用するならハンドシェイクにかかる時間も入るのかなと思ったのだがどうやら違うっぽい。

forum.nginx.org

Nginxのフォーラムで質問が書かれていてrequest_timeには含まれないよっていう回答がされていた。SSLハンドシェイクで遅くなっていると外形監視とかでレスポンスタイム悪くなっているけどnginxのログ見ても分からないよねみたいなのが発生したりする。

ついでなので実装も見てみる

処理時間を計算している箇所は以下。現在時刻とngx_http_request_tのr->start_secの時間の差分を処理時間としている

static u_char *
ngx_http_log_request_time(ngx_http_request_t *r, u_char *buf,
    ngx_http_log_op_t *op)
{
    ngx_time_t      *tp;
    ngx_msec_int_t   ms;

    tp = ngx_timeofday();

    ms = (ngx_msec_int_t)
             ((tp->sec - r->start_sec) * 1000 + (tp->msec - r->start_msec));
    ms = ngx_max(ms, 0);

    return ngx_sprintf(buf, "%T.%03M", (time_t) ms / 1000, ms % 1000);
}

github.com

ngx_http_request_tを初期化している箇所を探すとngx_http_alloc_requestっていう関数になるバックトレースを見るとわかるがSSLハンドシェイクは終わっている段階であった。

(gdb) bt
#0  ngx_http_alloc_request (c=0x7ffff7fa82e0) at src/http/ngx_http_request.c:549
#1  0x0000000000481a89 in ngx_http_create_request (c=0x7ffff7fa82e0)
    at src/http/ngx_http_request.c:514
#2  0x0000000000481a36 in ngx_http_wait_request_handler (rev=0x7f8b30)
    at src/http/ngx_http_request.c:496
#3  0x000000000045c573 in ngx_epoll_process_events (cycle=0x7c5900, timer=57433, flags=1)
    at src/event/modules/ngx_epoll_module.c:901
#4  0x0000000000449207 in ngx_process_events_and_timers (cycle=0x7c5900)
    at src/event/ngx_event.c:248
#5  0x00000000004597fc in ngx_worker_process_cycle (cycle=0x7c5900, data=0x0)
    at src/os/unix/ngx_process_cycle.c:721
#6  0x0000000000456231 in ngx_spawn_process (cycle=0x7c5900,
    proc=0x459715 <ngx_worker_process_cycle>, data=0x0, name=0x538a5a "worker process", respawn=-3)
    at src/os/unix/ngx_process.c:199
#7  0x000000000045876b in ngx_start_worker_processes (cycle=0x7c5900, n=1, type=-3)
    at src/os/unix/ngx_process_cycle.c:344
#8  0x0000000000457e6f in ngx_master_process_cycle (cycle=0x7c5900)
    at src/os/unix/ngx_process_cycle.c:130
#9  0x00000000004127d0 in main (argc=1, argv=0x7fffffffe9b8) at src/core/nginx.c:383

計測するなら

curlを使うとよさそう。time_appconnectがまさにそれなのでPrometheus形式なりMackerel形式なりに整形して出力するだけでメトリクスとしては十分なはず。

$ curl -so /dev/nul -w "http_code: %{http_code}\ntime_namelookup: %{time_namelookup}\ntime_connect: %{time_connect}\ntime_appconnect: %{time_appconnect}\ntime_pretransfer: %{time_pretransfer}\ntime_starttransfer: %{time_starttransfer}\ntime_total: %{time_total}\n" https://www.google.com/
http_code: 200
time_namelookup: 0.005496
time_connect: 0.017471
time_appconnect: 0.098974
time_pretransfer: 0.101247
time_starttransfer: 0.194621
time_total: 0.194858

#  time_appconnect
                             The  time,  in  seconds, it took from the start until the SSL/SSH/etc
                             connect/handshake to the remote host was completed. (Added in 7.19.0)