OpenCensusとhttptrace.ClientTraceを使ってHTTPリクエストのlatencyを可視化する

はじめに

みなさんこんにちは。これはGo5 Advent Calendar 2019の19日目の記事です。この記事はOpenCensusとhttptrace.ClientTraceを使ってHTTPリクエストの内部的なlatencyを可視化する話です。「内部的なlatency」というのは、HTTPリクエストの中で名前解決にどのぐらいかかったとか、コネクションを張るのにどのぐらいかかったなどです。

なお、この記事に記載しているコードは全てGitHub repositoryに上げてあります。

やりたいこと

とあるアプリケーションでHTTP Clientを使ってHTTPリクエストを大量に送る処理がありました。そのサーバーはUS Regionで動いていて、そこからHTTPリクエストを日本にあるサーバーに送るというもので、この処理のlatencyが非常に気になっていました。そのため、HTTPリクエストのどの部分が遅いのかを可視化したいと思って調べたところ、OpenCensusとhttptrace.ClientTraceに行き着いたのでその紹介をしたいと思います。

OpenCensusと分散トレーシング

今回使うのはOpenCensusのTracingという機能です。いわゆる分散トレーシングと呼ばれるものですが、詳しく説明していると長くなるので、詳細は以下の記事を読んでみて下さい。OpenCensusや分散トレーシングについてとてもよくまとまっています。

future-architect.github.io

Span

分散トレーシングではSpanというものを一つの処理の単位として登録します。例えば以下のようなGoのコードでは、main関数でSpanを1つ作り、main関数からfunc1, func2を呼び出して、それぞれの関数でも新しくSpanを作っています。

これをJaegerという分散トレーシングを可視化するソフトウェアで表示したものが以下になります。

trace: main
- trace: func1
- trace: func2

というようにSpanがツリー構造になっていて、それぞれのSpanでどのぐらい時間がかかっているかがわかると思います。この論理的にまとまったSpanたちがTraceと呼ばれています。

httptrace.ClientTrace

httprace.ClientTraceはHTTPリクエストの中で行われる以下の処理について、処理が開始したタイミングと終了したタイミングでコールバックを設定してイベントを受け取ることができるライブラリで、以下のようなコールバックが定義されています。詳しくはClientTraceのgodocを読むと良いでしょう。参考までに、以下に定義されているコールバックのコメントとその日本語訳を記載しておきます。

GetConn
- GetConn is called before a connection is created or retrieved from an idle pool
- コネクションが生成されたもしくはアイドルプールから取得された時に呼ばれる
GotConn
- GotConn is called after a successful connection is obtained
- コネクションの確立が成功した時に呼ばれる
DNSStart
- DNSStart is called when a DNS lookup begins.
- 名前解決が始まった時に呼ばれる
DNSDone
- DNSDone is called when a DNS lookup ends.
- 名前解決が終了した時に呼ばれる
ConnectStart:
- ConnectStart is called when a new connection's Dial begins
- 新しいコネクションのDialが始まった時に呼ばれる
ConnectDone
- ConnectDone is called when a new connection's Dial completes.
- 新しいコネクションのDialが完了した時に呼ばれる
TLSHandshakeStart
- TLSHandshakeStart is called when the TLS handshake is started
- TLSハンドシェイクが始まった時に呼ばれる
TLSHandshakeDone
- TLSHandshakeDone is called after the TLS handshake with either the successful handshake's connection state, or a non-nil error on handshake failure.
- TLSHandshakeDoneは、TLSハンドシェイクの接続に成功している場合か、ハンドシェイクがerrorで失敗している場合のどちらでも、TLSハンドシェイクが完了した後に呼ばれる。
WroteHeaderField
- WroteHeaderField is called after the Transport has written each request header
- それぞれのリクエストヘッダーのが書き込まれた後に呼ばれる。ヘッダーが複数ある場合は何回も呼ばれることになる。
WroteHeaders: WroteHeaders is called after the Transport has written all request headers.
- 全てのリクエストヘッダーが書き込まれた後に呼ばれる。
WroteRequest: WroteRequest is called with the result of writing the request and any body.
- リクエストのBodyも含めてリクエストが書き込まれた後に呼ばれる。
GotFirstResponseByte
- GotFirstResponseByte is called when the first byte of the response headers is available.
- レスポンスヘッダーの最初の1バイトが読み込める状態になった時に呼ばれる

試しにそれぞれのコールバック関数でfmt.Printするだけの簡単な実装を書いて実行してみると、以下のように出力されました。どうやらこの順番でコールバックが呼ばれていることがわかります。

$ go run examples/client_trace/main.go
GetConn
DNSStart
DNSDone
ConnectStart
ConnectDone
TLSHandshakeStart
TLSHandshakeDone
GotConn
WroteHeaderField: Host
WroteHeaderField: User-Agent
WroteHeaderField: Accept-Encoding
WroteHeaders
WroteRequest
GotFirstResponseByte

ということで、httptrace.ClientTraceを使うとHTTPのコネクションの接続のタイミングやリクエストを送信したタイミングのイベントが受け取れるということがわかりました。

OpenCensus Tracing + httptrace.ClientTrace

それではOpenCensusの分散トレーシングとhttptrace.ClientTraceの2つを組み合わせてみましょう。以下のようにochttp.NewSpanAnnotatingClientTraceを使うことで、簡単にhttptrace.ClientTraceの情報をTraceのSpanに入れることができます。

上記のプログラムを実行して、Jaegerに送られたSpanを可視化したものが以下のスクリーンショットになります。先ほど紹介したGetConnやDNSStartなどがどのぐらい時間がかかったかが相対的にわかるようになっています。例えば、DNSStartは0.25msでDNSDoneは59.84msなので、59.84 - 0.25 = 59.59ms かかっていることになります。

これは以下の手順で見ることができます。

$ docker-compose up #jaegerを起動
$ go run examples/ochttp_client_trace/main.go #プログラムを実行
$ open http://localhost:16686/search # ブラウザでjaegerを開く

NewSpanAnnotatingClientTraceとspanAnnotator

先ほどのNewSpanAnnotatingClientTraceでは、内部的にコールバックを定義したspanAnnotatorを用意して、これをhttptrace.ClientTraceのそれぞれのコールバックとして登録しています。spanAnnotatorはSpanを持っていて、それぞれのコールバック関数の中でSpanに対してAnnotationを登録しています。

Annotationを登録する時にはtimestampも記録されているため、上のJaegerのスクリーンショットのように各コールバック関数のタイミングで相対的にどのぐらい時間がかかったのかがわかるようになっています。

参考までに、以下はspanAnnotatorのDNSStartとDNSDoneのコードです。

func (s spanAnnotator) dnsStart(info httptrace.DNSStartInfo) {
    attrs := []trace.Attribute{
        trace.StringAttribute("httptrace.dns_start.host", info.Host),
    }
    s.sp.Annotate(attrs, "DNSStart")
}

func (s spanAnnotator) dnsDone(info httptrace.DNSDoneInfo) {
    var addrs []string
    for _, addr := range info.Addrs {
        addrs = append(addrs, addr.String())
    }
    attrs := []trace.Attribute{
        trace.StringAttribute("httptrace.dns_done.addrs", strings.Join(addrs, " , ")),
    }
    if info.Err != nil {
        attrs = append(attrs,
            trace.StringAttribute("httptrace.dns_done.error", info.Err.Error()))
    }
    s.sp.Annotate(attrs, "DNSDone")
}