DeNA では社内 rubygems として geminabox を運用しているのだが(主に@Spring_MT と自分が管理している)、なんだか遅い気がして気になってきたので高速化した記録。リアルISUCON。
Geminabox とは
一応前置きとして Geminabox の解説をしておくと、社内 rubygems を立てる時に使える何かである。
弊社では proxy モードで動かしていて、geminabox に gem がダウンロードされていなければ、rubygems.org にアクセスしてダウンロードして保存する、という仕組みで利用している。
社内 rubygems を立てている動機としては主に次の２点がある。
- rubygems.org が落ちても業務が止まらないようにする
- 社内 gem のリリース場所を確保する
１番は言わずもがなであるが、２番については補足すると、Gemfile では github 指定で gem のインストールができるのだが、gemspec では github 指定はできないため、社内 gem に依存する社内 gem が出てきた時に欲しくなったという背景がある。
完全ミラーリングではないことを考えると１番に対しては中途半端といえばそうなのではあるが、運用に回っているような gem はすでにミラーリングされているため、デプロイは止まらずに済む。以前 rubygems.org が１時間程度落ちたことがあったが、十分に恩恵を受けられたポジティブ体験がある。
どれぐらい遅いのか
さて、どれぐらい遅いのかであるが、次の Gemfile で source の向先きを変えて bundle update を打った時の時間を比べてみた。
Gemfile.org
source 'https://rubygems.org'
gem 'geminabox'
gem 'unicorn'
gem 'rake'
gem 'server-starter'
gem 'oneline_log_formatter'
gem 'rack-ltsv_logger'
$ time BUNDLE_GEMFILE=Gemfile.org bundle update
real 0m7.559s
$ time BUNDLE_GEMFILE=Gemfile.dena bundle update
real 0m16.821s
２倍以上遅い。。。つらい。。。
メトリクス
アクセスログから最近 1000 request のメトリクスを取ってみた
左から合計時間、リクエスト回数、平均時間、エンドポイント
977.1919999999992 725 1.3478510344827574 /api/v1/dependencies
588.7679999999999 20 29.438399999999994 /specs.4.8.gz
21.343000000000085 8852 0.002411093538183471 /upload
13.126 11 1.1932727272727273 /gems/nokogiri-1.6.7.2.gem
12.523 3 4.174333333333333 /
5.936 2 2.968 /api/v1/gems
5.072 4 1.268 /gems/aws-sdk-core-2.2.31.gem
/api/v1/dependencies と /specs.4.8.gz が明らかに遅い。
静的ファイルを nginx で返す
/specs.4.8.gz へのアクセスがあまりにも遅いのは、明確に geminabox の ruby プロセスでファイルを返していたためだった。何も設定してなくてすみません。。。って感じだ。
geminabox のコード(具体的には lib/geminabox/proxy/hostess.rb)を読んで、nginx で返した方が良さそうなものを try_files で返すようにした。
root /path/to/data;
location @webapp {
proxy_pass http://webapp;
}
location ~ \.gz$ {
try_files $uri @webapp;
}
location ~ \.(rz|Z)$ {
try_files $uri @webapp;
}
location ~ ^/(yaml|Marshal\.4\.8|specs\.4\.8|latest_specs\.4\.8|prerelease_specs\.4\.8)$ {
try_files $uri @webapp;
}
location ~ \.gem$ {
try_files $uri @webapp;
}
curl で /specs.4.8.gz を叩いて 0.19 sec で返ってくるようになった ^^。
29sec が 0.2sec に改善💪
プロファイリング
stackprof
遅いエンドポイントはわかったが、コード的にはどこなのかわかりやすいように stackprof を仕込んでプロファイリングした。Geminabox::GemListMerge#hash が遅いようだ。
$ bundle exec stackprof tmp/stackprof-cpu-10055-1459421776.dump
==================================
Mode: cpu(1000)
Samples: 325 (11.68% miss rate)
GC: 72 (22.15%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
114 (35.1%) 97 (29.8%) block in Geminabox::GemListMerge#hash
234 (72.0%) 27 (8.3%) block in <class:Server>
23 (7.1%) 23 (7.1%) Geminabox::GemListMerge#ignore_dependencies
21 (6.5%) 21 (6.5%) OpenSSL::Buffering#readpartial
16 (4.9%) 16 (4.9%) block in Geminabox::GemListMerge#ensure_symbols_as_keys
35 (10.8%) 14 (4.3%) block in Geminabox::GemListMerge#merge
14 (4.3%) 12 (3.7%) block in Geminabox::GemListMerge#combine_hashes
3 (0.9%) 3 (0.9%) ensure in block in Timeout#timeout
3 (0.9%) 3 (0.9%) block in HTTPClient#do_get_block
2 (0.6%) 2 (0.6%) HTTPClient::SSLConfig#default_verify_callback
2 (0.6%) 2 (0.6%) HTTPClient::SSLConfig#add_trust_ca_to_store
2 (0.6%) 2 (0.6%) JSON#parse
2 (0.6%) 2 (0.6%) HTTPClient::Session#create_socket
2 (0.6%) 2 (0.6%) block (2 levels) in Timeout#timeout
3 (0.9%) 2 (0.6%) <top (required)>
3 (0.9%) 2 (0.6%) <module:Protection>
3 (0.9%) 1 (0.3%) HTTPClient::SSLSocketWrap#ssl_connect
1 (0.3%) 1 (0.3%) block in OpenURI::Meta#content_type_parse
1 (0.3%) 1 (0.3%) block in OpenSSL::SSL#verify_certificate_identity
1 (0.3%) 1 (0.3%) OpenSSL::Buffering#fill_rbuff
5 (1.5%) 1 (0.3%) block in #<Module:0x007fa419a37658>.new
1 (0.3%) 1 (0.3%) Geminabox::GemListMerge#collection
1 (0.3%) 1 (0.3%) OpenSSL::SSL::Nonblock#initialize
1 (0.3%) 1 (0.3%) URI::Generic#initialize
1 (0.3%) 1 (0.3%) Rack::Builder#use
1 (0.3%) 1 (0.3%) block in HTTPClient::SSPINegotiateAuth#reset_challenge
1 (0.3%) 1 (0.3%) <module:Protection>
1 (0.3%) 1 (0.3%) block in Geminabox::DiskCache#marshal_read
1 (0.3%) 1 (0.3%) Rack::Protection::Base#html?
1 (0.3%) 1 (0.3%) <module:Protection>
rack-lineprof
遅い場所の検討はついたので、そのあたりに絞って rack-lineprof を仕込んで、その箇所を通るリクエスト(つまり/api/v1/dependencies)を投げて結果を出した。remote_gem_list (rubygems.org の /api/v1/dependencies を叩くところ)が支配的に遅くて、あとは local_gem_list とのマージ処理がそこそこ遅い。
[Rack::Lineprof] ===============================================================
lib/geminabox/server.rb
| 95
| 96 get '/api/v1/dependencies' do
3561.2ms 40343 | 97 query_gems.any? ? Marshal.dump(gem_list) : 200
| 98 end
| 99
.......
| 213
| 214 def dependency_cache
1.0ms 30 | 215 self.class.dependency_cache
| 216 end
| 217
.......
| 253
| 254 def gem_list
3482.2ms 3 | 255 settings.rubygems_proxy ? combined_gem_list : local_gem_list
| 256 end
| 257
.......
| 261
| 262 def local_gem_list
2.3ms 18 | 263 query_gems.map{|query_gem| gem_dependencies(query_gem) }.flatten(1)
| 264 end
| 265
| 266 def remote_gem_list
3025.1ms 4 | 267 RubygemsDependency.for(*query_gems)
| 268 end
| 269
| 270 def combined_gem_list
3481.4ms 5 | 271 GemListMerge.from(local_gem_list, remote_gem_list)
| 272 end
| 273
.......
| 289 # Return a list of versions of gem 'gem_name' with the dependencies of each version.
| 290 def gem_dependencies(gem_name)
2.2ms 30 | 291 dependency_cache.marshal_cache(gem_name) do
| 292 load_gems.
| 293 select { |gem| gem_name == gem.name }.
lib/geminabox/gem_list_merge.rb
| 4
| 5 def self.from(*lists)
453.5ms 8 | 6 lists.map{|list| new(list)}.inject(:merge)
| 7 end
| 8
.......
| 12
| 13 def merge(other)
453.5ms 4 | 14 combine_hashes(other).values.flatten.sort do |x, y|
76.8ms 69765 | 15 x.values[ignore_dependencies] <=> y.values[ignore_dependencies]
| 16 end
| 17 end
.......
| 21 puts _list.size
| 22 puts _list.first.to_s
334.3ms 2 | 23 list.each do |item|
43.6ms 872 | 24 ensure_symbols_as_keys(item)
1.1ms 872 | 25 name = item[:name].to_sym
0.7ms 872 | 26 collection[name] ||= []
283.6ms 179169 | 27 collection[name] << item unless collection[name].include?(item)
| 28 end
| 29 collection
.......
| 35
| 36 def combine_hashes(other)
334.5ms 5 | 37 hash.merge(other.hash) do |key, value, other_value|
| 38 (value + other_value).uniq{|v| v.values[ignore_dependencies]}
| 39 end
.......
| 45
| 46 def ensure_symbols_as_keys(item)
40.9ms 1744 | 47 item.keys.each do |key|
4.9ms 6976 | 48 next if key.kind_of? Symbol
14.9ms 14824 | 49 item[key.to_sym] = item.delete(key)
| 50 end
| 51 end
/api/v1/dependencies.json は遅いよ
https://bundler.rubygems.org/api/v1/dependencies が遅いならどうしようもないかなぁと思うのであるが、geminabox 経由で叩くと異様に遅い。
geminabox 経由だと 3sec
$ time curl --silent 'https://geminabox/api/v1/dependencies?gems=rake%2Cflexmock%2Cparallel_tests%2Csimplecov%2Crr%2Ctimecop%2Ctest-unit%2Ctest-unit-rr%2Coj%2Cpry%2Cpry-nav%2Cfluent-plugin-s3%2Cfluent-plugin-forest%2Cfluent-plugin-record-reformer%2Cmsgpack%2Cjson%2Cyajl-ruby%2Ccool.io%2Chttp_parser.rb%2Csigdump%2Ctzinfo%2Ctzinfo-data%2Cstrptime' > /dev/null
3.195 total
bundler.rubygems.org 直接だと 1.6sec
$ time curl --silent 'https://bundler.rubygems.org/api/v1/dependencies?gems=rake%2Cflexmock%2Cparallel_tests%2Csimplecov%2Crr%2Ctimecop%2Ctest-unit%2Ctest-unit-rr%2Coj%2Cpry%2Cpry-nav%2Cfluent-plugin-s3%2Cfluent-plugin-forest%2Cfluent-plugin-record-reformer%2Cmsgpack%2Cjson%2Cyajl-ruby%2Ccool.io%2Chttp_parser.rb%2Csigdump%2Ctzinfo%2Ctzinfo-data%2Cstrptime' > /dev/null
1.661 total
どうやら geminabox が Marshal dump を返す /api/v1/dependencies ではなく、JSON を返す/api/v1/dependencies.json を呼んでいるようで、それが遅かった。さらにハッシュの key を symbol に直す処理を JSON.parse(body, symbolize_names: true) ではなく、自前で ruby コードでやっていたりしてそれも遅い要因となっているようだったので、/api/v1/dependencies を利用するように変更した。
time curl --silent https://bundler.rubygems.org/api/v1/dependencies.json\?gems\=rake,flexmock,parallel_tests,simplecov,rr,timecop,test-unit,test-unit-rr,oj,pry,pry-nav,fluent-plugin-s3,fluent-plugin-forest,fluent-plugin-record-reformer,msgpack,json,yajl-ruby,cool.io,http_parser.rb,sigdump,tzinfo,tzinfo-data,strptime > /dev/null
3.021 total
3.0sec が 1.6sec に改善💪
マージ処理が遅い
remote_gem_list と local_gem_list のマージに、ものよっては 1.1sec かかることもあった。ごにょごにょ弄った結果、0.04 sec に高速化することができた > https://github.com/geminabox/geminabox/pull/230/commits/39f5b2ff29be21895285c00654c73981b3750271
1.1sec が 0.04sec に改善💪
Accept-Encoding: gzip
curl で /api/v1/dependencies を叩くとほとんど差がなくなったので、良さそう😀 と思ったのだが、bundle update で叩くと rubygems.org の方が早い。
bundler のリクエストヘッダを見るために、bundler の net/http/persistent に connection.debug_output = $stdout をつけてヘッダを出すようにした。どうやら gzip と keep-alive を有効にしているようだ。
<- "GET /api/v1/dependencies?gems=rspec-support HTTP/1.1\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nAccept: */*\r\nUser-Agent: bundler/1.11.2 rubygems/2.5.1 ruby/2.3.0 (x86_64-apple
-darwin15.2.0) command/update options/ d01203161a479cba\r\nConnection: keep-alive\r\nKeep-Alive: 30\r\nHost: bundler.rubygems.org\r\n\r\n"
-> "HTTP/1.1 200 OK\r\n"
-> "Server: Cowboy\r\n"
-> "Date: Sat, 02 Apr 2016 16:27:42 GMT\r\n"
-> "Connection: keep-alive\r\n"
-> "Content-Type: application/octet-stream\r\n"
-> "X-Content-Type-Options: nosniff\r\n"
-> "Vary: Accept-Encoding\r\n"
-> "Content-Encoding: gzip\r\n"
-> "Transfer-Encoding: chunked\r\n"
-> "Via: 1.1 vegur\r\n"
gzip と keep-alive 有効にして２つの URL に連続で GET (速い)
$ time curl -v 'https://bundler.rubygems.org/api/v1/dependencies' 'https://bundler.rubygems.org/api/v1/dependencies?gems=rake%2Cflexmock%2Cparallel_tests%2Csimplecov%2Crr%2Ctimecop%2Ctest-unit%2Ctest-unit-rr%2Coj%2Cpry%2Cpry-nav%2Cfluent-plugin-s3%2Cfluent-plugin-forest%2Cfluent-plugin-record-reformer%2Cmsgpack%2Cjson%2Cyajl-ruby%2Ccool.io%2Chttp_parser.rb%2Csigdump%2Ctzinfo%2Ctzinfo-data%2Cstrptime' -H 'Accept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3' -H 'Accept: */*' -H 'User-Agent: bundler/1.11.2 rubygems/2.5.1 ruby/2.3.0 (x86_64-apple-darwin15.2.0) command/update options/ 2c0046654ef44b07' -H 'Connection: keep-alive' -H 'Keep-Alive: 30' > /dev/null
1.609 total
gzip も keep-alive も無効にして２つの URL に連続で GET (遅い)
$ time curl -v 'https://bundler.rubygems.org/api/v1/dependencies' 'https://bundler.rubygems.org/api/v1/dependencies?gems=rake%2Cflexmock%2Cparallel_tests%2Csimplecov%2Crr%2Ctimecop%2Ctest-unit%2Ctest-unit-rr%2Coj%2Cpry%2Cpry-nav%2Cfluent-plugin-s3%2Cfluent-plugin-forest%2Cfluent-plugin-record-reformer%2Cmsgpack%2Cjson%2Cyajl-ruby%2Ccool.io%2Chttp_parser.rb%2Csigdump%2Ctzinfo%2Ctzinfo-data%2Cstrptime' -H 'Connection: close' --no-keepalive > /dev/null
3.217 total
geminabox が rubygems.org にリクエストを送る処理を見ると、httpclient を使っていて、keepalive はデフォルトで有効になっているようであるが、Accept-Encoding: gzip はつけていないようなので付けるようにして高速化した。
def http_client
- @http_client ||= HTTPClient.new(ENV['http_proxy'])
+ @http_client ||= HTTPClient.new(ENV['http_proxy']).tap {|client|
+ client.transparent_gzip_decompression = true
+ }
end
1.4sec が 1.1sec に改善 💪
nginx の設定
bundler が rubygems.org に期待しているのと同様の挙動をするように nginx の設定をした。具体的には
- keekpalive を有効 (
keepalive_timeout を伸ばして、keepalive_requests を増やした) gzip on にした- ついでに nginx => upstream の接続も keepalive させた (アプリの特性上、これはさほど影響しないが)
http session の再利用頻度を増やすために puma に置き換える
Geminabox を動かすための HTTP サーバとして unicorn を使用していた。また、多数のユーザをさばけるようにプロセス数を比較的大きめにしていた (Geminabox の特性上、CPUはほとんど使われない)。
bundle update を打つと、
Fetching gem metadata from https://rubygems.org/..............
Fetching version metadata from https://rubygems.org/...
Fetching dependency metadata from https://rubygems.org/..
のように表示されるが、この１つの . に付き、１回 /api/v1/dependencies を呼んでおり、それを keepalive connection で連続的に叩いている。
さて、このような前提において、geminabox に連続的にリクエストしても、リクエストごとに別の unicorn worker がリクエストを処理することになり、それぞれが /api/v1/dependencies を個別に叩くため、httpclient の keepalive (session reuse) が有効に働いていないようだ。特に https 接続するので SSL session の開始に時間がかかっている。
そこで、http session の再利用頻度を増やしつつ、しかし並列度は下げないために、HTTPサーバを unicorn から puma に置き換えた。なお、httpclient はスレッドセーフに作られているので、問題なく利用できた🙏
FYI: SSL session の開始に時間がかかる問題に関しては、rubygems.org へのアクセスを https から http に切り替えるという手もある。。。オススメはできないが速さだけを求めるならこれで大分速くなるだろう。
まとめ
高速化結果
- rubygems.org: 7.559 sec
- BEFORE: 16.821 sec
- AFTER: 8.543 sec
1secぐらいの差なら許容できるのではないだろうか！！💪
補足：/api/v1/dependencies が返すデータの量が大きいと Marshal.load/dump およびマージにかかる時間が増えるので rubygems.org 直接の場合との差が大きくなりやすい
Geminabox の変更
PR 送ってある > https://github.com/geminabox/geminabox/pull/230
Nginx の設定ファイル
ちょっと端折っているが、こんな感じ
http {
root /path/to/data;
gzip on;
proxy_http_version 1.1;
proxy_set_header Connection '';
proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-Host $host;
proxy_set_header X-Forwarded-Server $host;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded-Proto https;
upstream webapp {
server 127.0.0.1:3000 fail_timeout=0;
keepalive 32;
}
server {
listen 443 ssl;
keepalive_timeout 75;
keepalive_requests 100;
location @webapp {
proxy_pass http://webapp;
}
location / {
proxy_pass http://webapp;
}
# see lib/geminabox/proxy/hostess.rb
location ~ \.gz$ {
try_files $uri @webapp;
}
location ~ \.(rz|Z)$ {
try_files $uri @webapp;
}
location ~ ^/(yaml|Marshal\.4\.8|specs\.4\.8|latest_specs\.4\.8|prerelease_specs\.4\.8)$ {
try_files $uri @webapp;
}
location ~ \.gem$ {
try_files $uri @webapp;
}
}
}
なお、nginx の conf を書くときは nginx 実践入門が役に立つようだ😀
Puma の設定ファイル
宗教上の理由で puma on server-starter on daemontools にして動かしているが、それを除くとこれぐらい。
APP_ROOT = File.dirname(__FILE__)
pidfile File.join(APP_ROOT, 'tmp/pids/puma.pid')
state_path File.join(APP_ROOT, 'tmp/pids/puma.state')
preload_app!
threads 0, 16
workers 2
server starter の puma 対応はこちらをご参照ください > ruby-server-stater/example/puma