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")
}

まとめ

OpenCensusとhttptrace.ClientTraceを組み合わせることで、HTTPリクエストの詳細なlatencyを可視化する方法を紹介しました。

私の場合は、この情報を元にして「コネクションの確立に時間がかかっているから、KeepAliveを長い時間有効にしてなるべくコネクションを使いまわそう」という感じでパフォーマンスチューニングの役に立てています。この記事が何かしらのパフォーマンスチューニングの役に立てば嬉しいです。

改訂2版 みんなのGo言語

Go言語における並行処理 - ユースケース編

はじめに

これは以下の記事の続きの記事。以下の2つではgoroutineとchannelについて説明したので、これらを使って具体的な並行処理のユースケースを書いてみる。

• Goにおける並行処理 - goroutine編 - oinume journal
• Goにおける並行処理 - channel編 - oinume journal

goroutineによる並行処理がすべて終わるまで待つ

処理を複数のgoroutineで並行で実行したい、というのはよくある例。起動したgoroutineがすべて終わるまで待ちたいときには、以下のようにsync.WaitGroupを使う。

package main

import (
    "fmt"
    "sync"
)

func main() {
    var wg sync.WaitGroup
    for i := 1; i <= 20; i++ {
        wg.Add(1) // カウンターをインクリメントする
        go func(i int) {
            fmt.Printf("i = %02d, fibonacci = %04d\n", i, fibonacci(i))
            defer wg.Done() // 処理が終わったのでカウンターをデクリメントする
        }(i)
    }
    wg.Wait() // カウンターが0になるまで待つ
    fmt.Println("Done")
}

func fibonacci(n int) int {
    if n <= 1 {
        return n
    }
    return fibonacci(n-1) + fibonacci(n-2)
}

goroutineで並行処理する数に上限を設けたい

よくある要件として「同時に実行する数を制限したい」があるが、この場合はセマフォというパターンで実装する。具体的には、Goであればchannelにバッファが付けられるので、このバッファの数で同時実行数を制限できる。

package main

import (
    "flag"
    "fmt"
    "io/ioutil"
    "net/http"
    "regexp"
    "sync"
    "time"
)

var (
    concurrency = flag.Int("c", 1, "num of concurrency")
)

func main() {
    flag.Parse()
    semaphore := make(chan struct{}, *concurrency) // 同時実行数
    var wg sync.WaitGroup
    urls := []string{
        "https://journal.lampetty.net/entry/what-i-like-about-heroku",
        "https://journal.lampetty.net/entry/e2e-test-with-agouti-in-go",
        "https://journal.lampetty.net/entry/heroku-custom-clock-processes",
        "https://journal.lampetty.net/entry/mac-settings-on-sierra",
        "https://journal.lampetty.net/entry/mysqldump-option-where",
        "https://journal.lampetty.net/entry/introducing-lekcije",
        "https://journal.lampetty.net/entry/intellij-shortcuts-for-reading-source-code",
        "https://journal.lampetty.net/entry/introducing-dead-mans-snitch",
        "https://journal.lampetty.net/entry/concurrency-in-go-channels",
        "https://journal.lampetty.net/entry/concurrency-in-go-goroutines",
        "https://journal.lampetty.net/entry/cancel-and-timeout-with-context-in-go",
        "https://journal.lampetty.net/entry/gcp-cloud-pubsub-memo",
        "https://journal.lampetty.net/entry/oauth2-client-handson-in-go-authorization-code-grant",
        "https://journal.lampetty.net/entry/satisfying-a-large-interface-quickly-in-go",
    }
    for _, u := range urls {
        wg.Add(1)
        u := u
        go func() {
            defer wg.Done()
            fetch(semaphore, u)
        }()
    }
    wg.Wait()
}

var r = regexp.MustCompile(`<title>(.*)</title>`)

func fetch(semaphore chan struct{}, url string) {
    semaphore <- struct{}{}
    defer func() {
        <-semaphore
    }()
    time.Sleep(3 * time.Second)
    resp, err := http.Get(url)
    if err != nil {
        fmt.Printf("err = %v\n", err)
        return
    }
    defer func() { _ = resp.Body.Close() }()

    bytes, err := ioutil.ReadAll(resp.Body)
    if err != nil {
        fmt.Printf("err = %v\n", err)
        return
    }
    body := string(bytes)
    if group := r.FindStringSubmatch(body); len(group) > 0 {
        fmt.Printf("%v\n", group[1])
    }
}

上記のプログラムはURLのリストからhttp.Getしてtitleだけを表示するプログラムである。ここではsemaphoreというバッファ付きのchannelを使って、以下のように同時実行数を制限できるようにしている。

• mainの中でsemaphoreを生成
• fetch関数にsemaphoreを渡す
• fetchの内部で、処理を実行する前にsemaphoreにデータを入れて、処理が終わったらdeferでsemaphoreからデータを取り出している。これによりchannelのバッファを超える場合は処理がブロックされるようになる

以下のように実行時に-c 3と指定することで、同時にhttp.Getする数が3つに制限されてコンソールに出力される数が3行ずつになるはず。

$ go run semaphore.go -c 3

Herokuの好きなところ - oinume journal
Better Heroku Schedulerを探したらCustom clock processesにたどり着いた - oinume journal
WebアプリケーションのE2EテストをGoで書く - oinume journal
...

バックグラウンドで一定の間隔で処理を行いたい

これはtime.Tickerとselectを使うことで簡単に実装できる。以下は1秒ごとにdoSomethingを呼び出すプログラム。

package main

import (
    "fmt"
    "time"
)

func main() {
    ticker := time.NewTicker(time.Second)
    defer ticker.Stop()
    for i := 0; i < 10; i++ {
        select {
        case <-ticker.C:
            doSomething(i)
        }
    }
}

func doSomething(v int) {
    fmt.Printf("%d\n", v)
}

まとめ

ユースケースについては探せばもっとありそうだけど、よくありそうな並行処理の実装パターン3つを紹介した。何かのためになれば幸いです。

Go言語による並行処理

2019年9月の振り返り

8月の振り返りをサボってしまったのでまとめて。

アウトプット

Goの並行処理の記事とMySQL 8.0へアップデートする記事を書いた。

• Goにおける並行処理 - goroutine編 - oinume journal
• Goにおける並行処理 - channel編 - oinume journal
• Problems when updating MySQL from 5.7 to 8.0 - oinume journal

睡眠

1日6時間以上寝る、ということを今年の目標にしている。ヘルスケアアプリによると

• 8月: 6h10min
• 9月: 5h59min

という感じで9月はギリギリで未達成。しかもこれ平均で平日は大体5時間ぐらいなのでかなりやばめ。

英語

9月にIELTSのテストを受けてきた。詳細については以下にまとめたけど、感触としては悪くない気がする。ちなみに11月にTOEICも受ける予定。あと来年前半にTOEFLもおそらく受ける。

https://journal.lampetty.net/entry/taking-ielts-test-first-time:ttile

アルゴリズム

特に進捗なし

Go, gRPC, SQLの復習

引き続き Go言語による並行処理 を読んでいる。あと一つ記事を書きたい。

まとめ

まぁボチボチ頑張る。

初めてIELTSを受験した

IELTSってなに？

国際的な英語の試験。大学の入学の条件に使われたり、国によっては永住権を申請する時のポイントとして使われるもの。

会場

自分は東京会場で、場所は幸ビルディングという新橋付近の貸し会議室っぽいところだった。

持ち込みできるもの

中に持っていけるものは

• 鉛筆
• 消しゴム
• パスポート
• パスポートのコピー
• 水

のみOK。なお、鉛筆はお願いすれば試験の最中に試験官が削ってくれるので、鉛筆削りは持っていなくても大丈夫。

会場に着いてから

1. 荷物を預ける
2. IDチェック
3. 試験室に入室

という流れ。

会場のビルの会議室でビニール袋に荷物を詰めて預ける。8:40にはこの荷物置き場が物理的に閉鎖されるので、それまでに会場に着いて荷物を預ける必要がある。

その後IDチェック。これをやったあとにトイレに行こうとすると再度指紋認証する必要がありめんどいので先にトイレは済ませておいたほうが良い。IDチェックでは指紋を採取されさらにカメラで写真を取られる。パスポートの顔写真と同一人物かも当然チェックされる。

終わると、試験官と一緒に試験する別の部屋に行く。

感想

受験者は予想通り若い人が多かった印象。驚いたのは、20%ぐらいは外国人(見た目で明らかに日本人じゃないとわかる人)だったこと。アフリカ系の人やインド系の人が多かった。もしかしたら中国人や韓国人も結構いたのかもしれない。カップルで受験している人もちらほらいた。自分みたいな40代のおっさんは1%ぐらいしかいない雰囲気だった。

IELTSの試験

意外なことに

1. Writing
2. Reading
3. Listnening

という順番だった。というのは、参考書ではListening, Reading, Writing, Spreakingの順番で問題が構成されていたから、順番が全然違うことにびっくりした。もろもろのアナウンスが終わって9:20頃から試験がスタートした気がする。

• Writing: 40分
• Reading: 60分
• Listening: 30分

という時間配分で、12:30ごろには終わった。それぞれのパートの合間で問題や解答用紙を回収する時間があるので、少し休めるのは良かった。TOEICと比べるとこの休憩時間があるおかげでそこまで疲労感を感じなかった気がする。なお、Speakingは午後にあり、自分は15:20開始だったので、昼ごはんを食べて新橋駅付近のカフェで時間を潰していた。

Writing

トピックは

• Task1: 友人に仕事(求人)を薦める時に、仕事内容、なぜその人にオススメするのか、求人への応募方法をレター風味で書く
• Task2: 保育園に子供を預けることと、預けないで家族が育てることについての意見を述べよ

というもので、どちらも自分にとっては馴染みのあるものだった。なので、書く内容を日本語でまとめておいて、あとはそれをひたすら英語に訳すというスタイルで書いていった。Task1は130 word以上で、ギリギリかけた。一方、Task2は250 word以上なので、圧倒的に時間が足りなくて文章の途中で終わってしまった。Writingは「字数が足りないからあとから文章を付け足す」ということがとてもやりにくいので、英文を書き始める前にちゃんと書く内容を決めておくことが大事だと思った。Computer Basedなテストだったら文章の間に別の文を挿入したりするのが簡単にできたりするんだろうか、などと考えた。

とにかく仕事ではこういう風に文章を書くことがあまりないので(デジタルなら後からいくらでも文章を付け足したり入れ替えたりできるので)、時間配分も含めて痛いミスをしてしまったように思う。Task2はおそらく100 wordぐらいしか書けていない。

Reading

最後のsection以外はそこまで難しくなかった。あと時間が圧倒的に足りないかなと思ったけど、ギリギリ終わるレベルだった。例えばTOEICだと明らかに時間内に終わる量ではないので、それに比べれば時間的な厳しさはなかったように思う。

Listening

Section1はたしかに一番簡単だった。ただ、選択式ではなく単語を埋めるタイプなので、冠詞をつけるかつけないかでけっこう悩んだ。Section4がやはり最高に難しくて、2,3問合っていればいいか、ぐらいのノリ。

Speaking

これは外国人の試験官に連れられて小さい会議室で実施された。"How are you?" とか少し雑談してice breakしてから本試験が始まる。内容としては

• 学生 or 仕事している？
• 仕事で一番興味深いことはなに？
• どんな音楽を聴く？
• 音楽を聴くときは一人で聴くのが好き？それとも他の人と聴くのが好き？

というような質問をされた。案の定Speakingが一番難易度が高いというか、普段の実力値が出てしまうのでこれが一番点数低そうだなと思った。

まとめ

試験の2週間前にIELTSの問題集をやって「うわっなにこれ難しすぎ」と絶望していたのだけど、本試験は意外と難しくなく、少しホッとした。スコアは10/13頃に送付されるらしいので、どのぐらいできているのか楽しみ。5.0〜6.0の間ぐらいだと思うんだけどどうなることやら。

【音声ダウンロード付】IELTSブリティッシュ・カウンシル公認問題集

Problems when updating MySQL from 5.7 to 8.0

Introduction

I updated MySQL from 5.7 to 8.0. There were some problems when updating. This is just a memo how to solve the problems.

InnoDB deprecated file format parameters

These parameters are deprecated in 8.0.

• innodb_file_format
• innodb_file_format_check
• innodb_file_format_max
• innodb_large_prefix

ref: MySQL :: WL#7704: InnoDB: Remove deprecated file format parameters in 8.0

Query cache parameters are deprecated

These parammeters are deprecated in 8.0.

• query_cache_limit
• query_cache_size

ref: https://mysqlserverteam.com/mysql-8-0-retiring-support-for-the-query-cache/

innodb_support_xa

innodb_support_xa is deprecated as well.

ref: MySQL :: WL#8843: Deprecate and remove the parameter innodb_support_xa

Can't create users with GRANT

You can't create users with GRANT operation. For example, you need to change

GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER, LOCK TABLES ON db.* TO 'user'@'%' IDENTIFIED BY 'yourpassword'

like this:

CREATE USER IF NOT EXISTS 'user'@'%' identified by 'yourpassword';
GRANT SELECT, INSERT, UPDATE, DELETE, CREATE, DROP, INDEX, ALTER, LOCK TABLES ON db.* TO 'user'@'%';

ref: How to grant all privileges to root user in MySQL 8.0 - Stack Overflow

default-authentication-plugin

The default value of default-authentication-plugin is caching_sha2_password. If your MySQL driver doesn't support the authentication method, you'll get an error this authentication plugin is not supported. mysql_native_password is the default value in MySQL 5.7 so you can specify it like this:

default-authentication-plugin = mysql_native_password

Other problems I've faced with

TABLE_NAMES from information_schema

My program executes following query.

SELECT table_name FROM information_schema.tables WHERE table_schema = 'mydb';

+------------------------------------+
| TABLE_NAME                         |
+------------------------------------+
| event_log_email                    |
| following_teacher                  |
| goose_db_version                   |
| lesson                             |
| lesson_status_log                  |
| m_country                          |
+------------------------------------+

The result of the query is TABLE_NAME in 8.0 although it was table_name in 5.7. As a result, I changed my query like this:

SELECT TABLE_NAME AS table_name FROM information_schema.tables WHERE table_schema = 'mydb';