Go 言語で Apache Bench (ab) を実装してみた

Go 言語で Apache Bench (ab) を実装してみた。

なぜか

以前、wc コマンドを実装した。その時に ab も候補に入っていたけど、ab は http 通信をするプログラムなので、より単純な wc を選択したのだった。その次に何やるか、ということで http クライアントのコードを書く練習になりそうな ab を実装してみることにした。

期間は2016年10月から1ヶ月くらいやったあと、2ヶ月くらいブランクがあって、2017年1月に再開して一ヶ月くらいやっていた。コツコツとよく続いたと思う。

Apache Bench (ab) とは

Apache Bench (ab) は HTTP サーバーの性能を測定するためのプログラムでシングルスレッドで動作する。Apache HTTP サーバーのソースコードに含まれており、オープンソースである。

以下のように実行すると、同時に 10 リクエストずつ、計 100 回の HTTP GET リクエストを行い、結果を集計して表示してくれる。

ab -n 100 -n 10 http://example.com/

Golang の他の実装

hey というプログラムがある。これは Python の boom というプログラムに影響を受けて作成されたらしい。まさしく、な代物だけど、今回の目的を果たすまではこのコードは決して見るまいと心に決めた。それは見ると絶対に影響を受けてしまって自分の創造性が損なわれて今回の目的（学習）にはマイナスに作用すると判断したため。

どう進めたか

最初から計画していたわけではないけど、結果的にこのような進め方になった。

ab の理解
ab の入出力を完コピする
ベンチマークの取得と問題の発生
発生した問題の解決
改めてベンチマークの取得

1. ab の理解

ab を実装するには、まずは ab が何をやっているのか知る必要がある。だから、ab の出力を見ながらコードを読んだ。

ab のコード https://github.com/apache/httpd/blob/trunk/support/ab.c

ab の出力:

ab -n 100 -c 10 http://localhost:8000/
This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:
Server Hostname:        localhost
Server Port:            8000

Document Path:          /
Document Length:        13 bytes

Concurrency Level:      10
Time taken for tests:   0.013 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      13000 bytes
HTML transferred:       1300 bytes
Requests per second:    7774.84 [#/sec] (mean)
Time per request:       1.286 [ms] (mean)
Time per request:       0.129 [ms] (mean, across all concurrent requests)
Transfer rate:          987.04 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       1
Processing:     0    1   0.2      1       1
Waiting:        0    1   0.2      1       1
Total:          1    1   0.3      1       2

Percentage of the requests served within a certain time (ms)
  50%      1
  66%      1
  75%      1
  80%      1
  90%      2
  95%      2
  98%      2
  99%      2
100%      2 (longest request)

ポイントは以下の2つ。

リクエストの送信方法
- ab は Apache Portable Runtime (APR) というライブラリを使っている
- apr_socket_send という関数でリクエストを送っている
- apr pollset API というのを使って I/O の多重化をしている
時間の計測
- 処理の合間合間に細かく時間を記録してる
- Requests per second はリクエスト数を始まりの時間と終わりの時間の差分で割っているだけ
集計
- 全リクエストの結果を最後に集計して Connection Times の欄を出力している。最小、最大、平均、中間、標準偏差を出している

2. ab の入出力を完コピする

ab がやっていることがわかれば、あとはひたすら実装していくだけ。

Connection Times の出力

時間の計測をどうやるか？というのだけ想像できなかったの調べたら net/http/httptrace というドンピシャなパッケージがあったので助かった。これを使うと HTTP リクエストのいくつかのタイミングをフックできるので、そこで時間を計測できる。最初は ab の出力に合わせて Connect, Processing, Waiting, Total という項目を出していたけど、バカバカしくなって途中から httptrace で取得できる項目だけを出すことにした。またここだけは自分で実装するのをやめて go-httpstat を使わせてもらった。大変便利。で、最終的に以下のような出力になった。

Connection Times (ms)
                     min  mean[+/-sd] median   max
DNSLookup:             1    2   1.4      1       5
TCPConnection:         1    1   1.1      1       3
TLSHandshake:          0    0   0.5      0       0
ServerProcessing:      1    1   1.0      1       4
ContentTransfer:       1    1   0.7      1       2
Total:                 1    3   2.0      2       8

標準偏差

[+/-sd]の項目が標準偏差（Standard Deviation）。この辺りの知識に疎かったので勉強になった。標準偏差を見るとデータのばらつき具合がわかる。値が大きいとばらつきが大きいということなので、ベンチマークの結果が安定してないのかな？という気づきが得られる。おもしろいなーと思った。

3. ベンチマークの取得と問題の発生

最後にベンチマークをとった。

計測方法

Golang で簡単なサーバーを立てる https://github.com/takatoshiono/go-ab/blob/master/test/server.go
Concurrency を 1 から 100 まで 10 刻みで増やしながら秒間リクエスト数を計測

ベンチマーク用のスクリプトを書いて（かなり書きなぐってます）実行すると途中でしばらく止まってしまうという問題が発生した。ab が apr_pollset_poll: The timeout specified has expired (70007) というエラーを出している。何回やっても同じ。単独で ab -n 20000 とかやっても 16000 くらいで同じように止まってしまう。

4. 発生した問題の解決

いろいろ調べていたらポートの問題だということがわかった。

‘ab’ program freezes after lots of requests, why? - Stack Overflow

TCP/IP 通信をするためにはIPアドレスとポートが必要。サーバー側の接続ポートは決まっているけど、クライアント側は特に決まっていなくて一時的なポート (Ephemeral Port) が割り当てられる。このポートの数には上限があって Mac OS X だと 16000 くらいだった。TCP/IP 接続ではクライアント側からポートを閉じた後に一定時間だけサーバー側からの応答を待つフェーズというのがあって、それが TIME_WAIT というステータスで表されている。今回はこの TIME_WAIT 状態のポートがたまりすぎて Ephemeral Port を使い果たしてしまったというオチだった。

どうするか

ベンチマークの実行間隔をあける
- TIME_WAIT になったポートは一定時間待てば解放される。時間を計ったらだいたい 30 秒くらい待てばよさそうだったので、Concurrency を上げるタイミングで 30 秒スリープしながらベンチマークを実行することにした
KeepAlive 接続にする
- TCP/IP 接続を使いまわして複数の通信をする KeepAlive を使えば問題は起きない

実装の見直し

Golang ではデフォルトで KeepAlive になるようなのだがベンチマーク実行中のポートの状況を見ていると Concurrency で指定した数より多くのポートを使っていた。そうではなく、Concurrency と同じ数のポートだけ使いたい。hey はそのような動きをしていたので、ここにきて初めてコードを読み始めた。あとは net/http パッケージのドキュメントや net/http 周りのコードを読みながら調査を進めた。

ガチャガチャとコードをいじってみてもよくわからなかったので、仕切り直して最小限のコードを書いて1つずつ実験してみて、ようやくわかったのだった。

答え：1 ゴルーチン、1 http.Transport を使えばよい
- http.Transport というのは RoundTripper インターフェースの実装で、HTTP 通信をするのに使用する。これは内部で接続をキャッシュするとドキュメントには書いてあった。ここからは想像だけど、同じ Transport を複数のゴルーチンで使い回す場合、ある程度の数のポートをゴルーチン間で使いまわすようになっているのかもしれない。

以下に試したことを書いておく。

http.Get

この関数を複数のゴルーチンから叩く。http.Get が最もシンプルな方法だと思う。

func (b *Benchmark) Get(n int) {
     for i := 0; i < n; i++ {
          resp, err := http.Get(b.url)
          if err != nil {
               log.Fatal("GET %s failed: %+v\n", b.url, err)
          }
          io.Copy(ioutil.Discard, resp.Body)
          resp.Body.Close()
     }
}

問題は解消せず。

http.Request を使い回す

http.Get(url) は http.DefaultClient.Get(url) と同じなので Client.Get を見ると NewRequest してから Client.Do(req) している。そこで NewRequest をリクエストごとにやらずに使いまわして見た。

func (b *Benchmark) Get2(n int) {
     req, err := http.NewRequest("GET", b.url, nil)
     if err != nil {
          log.Fatal("NewRequest failed: %+v\n", err)
          return
     }

     for i := 0; i < n; i++ {
          resp, err := http.DefaultClient.Do(req)
          if err != nil {
               log.Fatal("GET %s failed: %+v\n", b.url, err)
          }
          io.Copy(ioutil.Discard, resp.Body)
          resp.Body.Close()
     }
}

問題は解消せず。

http.Client も使い回す

http.DefaultClient は &Client{} のことで、この場合はデフォルトの Transport として http.DefaultTransport が使われる。このへんを見ると書いてある。ということで、こういうコードにした。

func (b *Benchmark) Get3(n int) {
     client := &http.Client{Transport: http.DefaultTransport}

     req, err := http.NewRequest("GET", b.url, nil)
     if err != nil {
          log.Fatal("NewRequest failed: %+v\n", err)
          return
     }

     for i := 0; i < n; i++ {
          resp, err := client.Do(req)
          if err != nil {
               log.Fatal("GET %s failed: %+v\n", b.url, err)
          }
          io.Copy(ioutil.Discard, resp.Body)
          resp.Body.Close()
     }
}

問題は解消せず。

http.DefaultTransport を使わない

これで問題が解消した。Transport の設定を DefaultTransport と同じにしても問題は起きなかったので、設定値の問題ではなく、同じ Transport を複数のゴルーチンで使い回すか、ゴルーチンごとに Transport を作るかの違いなのだな、という結論になった。

func (b *Benchmark) Get4(n int) {
     // あれー？これでDefaultTransportと同じはずだけど、concurrencyぶんのportしか使われないぞ
     // goroutineごとにtransportを作るか、共通のtransportを使うかの違いかな
     var tr http.RoundTripper = &http.Transport{
          Proxy: http.ProxyFromEnvironment,
          DialContext: (&net.Dialer{
               Timeout:   30 * time.Second,
               KeepAlive: 30 * time.Second,
          }).DialContext,
          MaxIdleConns:          100,
          IdleConnTimeout:       90 * time.Second,
          TLSHandshakeTimeout:   10 * time.Second,
          ExpectContinueTimeout: 1 * time.Second,
     }
     client := &http.Client{Transport: tr}

     req, err := http.NewRequest("GET", b.url, nil)
     if err != nil {
          log.Fatal("NewRequest failed: %+v\n", err)
          return
     }

     for i := 0; i < n; i++ {
          resp, err := client.Do(req)
          if err != nil {
               log.Fatal("GET %s failed: %+v\n", b.url, err)
          }
          io.Copy(ioutil.Discard, resp.Body)
          resp.Body.Close()
     }
}