Ruby
Sinatra
rack

Sinatra+Thin環境で、DBにコネクションが張れないことがある問題について調査した

More than 1 year has passed since last update.

タイトルと内容にズレがあり誤解を招きそうなのでタイトルを直しました。

調査に用いたSinatraのアプリケーションコード(github)

概要

Sinatra+Thin+MySQLで簡単なAPIサーバを立てることを考えよう。

Sinatraアプリは公式で紹介されている2種類の起動方法があるが、それによってマルチスレッドか否か(rack.multithread)の動作モードに違いが出た。マルチスレッド版だと、デフォルトの設定でコネクションプール数が生えてくるワーカースレッドの数より小さいため、(コネクションプール数)+1回目のアクセスでエラーが起こる。この問題は、コネクションプール数をワーカースレッド数以上に設定することで解決できる。

両者の起動方法はRackが間に挟まるかどうかが異なり、Thinに渡されているオプションが異なる可能性がある。

以下は上記結論に至るまでに調べたこと、考えたことのメモ。

前提

アプリのコード

app.rb
require 'sinatra/base'
require 'active_record'
require 'mysql2'
require 'json'
require 'yaml'

class MyApp < Sinatra::Base
  connection_setting = YAML.load(ERB.new(File.read('database.yml')).result)
  ActiveRecord::Base.establish_connection connection_setting['development']

  class User < ActiveRecord::Base
  end

  get '/ranking' do
    User.order(score: :desc).limit(50).to_json
  end

  run! if app_file == $0
end

get /ranking にアクセスが行くと、登録されているユーザをscoreの降順に並べ、先頭から50件取ってJSONを返すようになっている。
今回、DBの処理そのものは本質的ではないので、(何かしらDBにアクセスしに行くコード)が入っていると考えてもらって構わない。

データベース

以下のように設定ファイルを書いて、

database.yml
development:
  adapter: mysql2
  database: writeapp_sinatra
  host: localhost
  username: root
  password:
  encoding: utf8

データベース writeapp_sinatra と、User に対応するテーブルをMySQLにて予め作成しておく。

-- データベース作成
mysql> create database writeapp_sinatra default character set utf8mb4;
Query OK, 1 row affected (0.00 sec)

-- データベースを writeapp_sinatra に切り替え
mysql> use writeapp_sinatra;
Database changed

-- users テーブルを作成
mysql> create table users (
    ->   id BIGINT UNSIGNED NOT NULL AUTO_INCREMENT,
    ->   name VARCHAR(255) NOT NULL,
    ->   score BIGINT NOT NULL,
    ->   PRIMARY KEY(id)
    -> );
Query OK, 0 rows affected (0.03 sec)

WebサーバはThin

RackおよびSinatraは Thin が利用可能である場合、それを使おうとするのでGemfileに入れておく。

source 'https://rubygems.org'

gem 'sinatra'
gem 'activerecord'
gem 'mysql2', '~> 0.3.20'
gem 'thin'

bundler を用いてインストールが終わったら、準備完了。

起動方法A

アプリを動かす

以下のようにしてSinatraアプリケーションを起動できる。

起動方法.A
bundle exec ruby app.rb

この方法で起動すると app.rb 末尾の if app_file == $0 が真になり、 Sinatra::Base#run! が実行される。

何回か /ranking にアクセスを試みると、DBに接続できていることがわかる。しかし、6回目のアクセスで、以下のエラーが表示される。

ActiveRecord::ConnectionTimeoutError - could not obtain a database connection within 5.000 seconds (waited 5.004 seconds):

規定の秒数待ってもDBにコネクションが貼れなかった、という趣旨のエラーだ。

MySQLのプロセスを確認

このままの状態で、MySQLのコンソールに入って現在動いているプロセスを確認してみる。

mysql> show processlist;

+----+------+-----------+------------------+---------+------+-------+------------------+
| Id | User | Host      | db               | Command | Time | State | Info             |
+----+------+-----------+------------------+---------+------+-------+------------------+
|  8 | root | localhost | NULL             | Query   |    0 | init  | show processlist |
| 39 | root | localhost | writeapp_sinatra | Sleep   |    9 |       | NULL             |
| 40 | root | localhost | writeapp_sinatra | Sleep   |    7 |       | NULL             |
| 41 | root | localhost | writeapp_sinatra | Sleep   |    7 |       | NULL             |
| 42 | root | localhost | writeapp_sinatra | Sleep   |    6 |       | NULL             |
| 43 | root | localhost | writeapp_sinatra | Sleep   |    6 |       | NULL             |
+----+------+-----------+------------------+---------+------+-------+------------------+

このように、5つ分のコネクションが開放されないまま残っている。MySQLの最大コネクション数は100程度なので、アプリ側がコネクションを保持したままになっていることが原因だろう。

デフォルトのコネクションプール数をActiveRecordのドキュメントで調べると

Options

There are several connection-pooling-related options that you can add to your database connection configuration:

**pool: number indicating size of connection pool (default 5)**

checkout_timeout: number of seconds to block and wait for a connection before giving up and raising a timeout error (default 5 seconds).

ActiveRecord::ConnectionAdapters::ConnectionPool

とあるので、この予想は正しいように思える。

起動方法B

ところで、Sinatraを動かすには別の方法がある。以下の様に config.ru というファイルを作成し、

config.ru
require 'sinatra'
require File.expand_path('../app.rb', __FILE__)

run MyApp

rackup を叩くとサーバが起動する。

bundle exec rackup

アプリを動かす

こちらは、何度アクセスしてもエラーは起こらない。

MySQLのプロセスを確認

MySQLのプロセスを確認すると、

mysql> show processlist;

+----+------+-----------+------------------+---------+------+-------+------------------+
| Id | User | Host      | db               | Command | Time | State | Info             |
+----+------+-----------+------------------+---------+------+-------+------------------+
| 91 | root | localhost | writeapp_sinatra | Sleep   |   41 |       | NULL             |
| 92 | root | localhost | NULL             | Query   |    0 | init  | show processlist |
+----+------+-----------+------------------+---------+------+-------+------------------+

コネクションは1つだけである。起動の仕方で、なぜこのような違いが起こるのだろうか。

何が起きているのか知る

rack envを確認

rack envはRackの動作モードが記述されている変数で、request.env で確認できる。get /ranking に出力するコードを仕込んで、両者の違いを見てみよう。

app.rb
  get '/ranking' do
    p request.env # 追加
    User.order(score: :desc).limit(50).to_json
  end

すると、以下の違いが確認できた。

rack.multithread = true
rack.multithread = false

rack.multithread とは何か。ドキュメントを読むと

rack.multithread
true if the application object may be simultaneously invoked by another thread in the same process, false otherwise.

File: SPEC - Documentation for rack/rack (master)

とある。つまり起動方法Aだとサーバがマルチスレッドで動いている・・・?

psで確認

より状況をはっきりさせるため、起動後、何回かアクセスした後に ps -M を実行しプロセスの上で走っているスレッドを確認する。

> ps -M
hama_du 18479 s007    0.0 S    31T   0:00.11   0:00.72 /Users/hama_du/.rbenv/versions/2.2.1/bin/ruby app.rb
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.01
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.03
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.01
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
        18479         0.0 S    31T   0:00.00   0:00.00
> ps -M
hama_du 18768 s007    0.0 S    31T   0:00.22   0:00.84 ruby /Users/hama_du/projects/backend-speed-experiment/sinatra-mysql/vendor/bundle/ruby/2.2.0/bin/rackup
        18768         0.0 S    31T   0:00.00   0:00.00

このように、起動方法Aでは複数(1+20個)のスレッドが走っていることが確認できた。この数は何度アクセスしても増える様子はなかった。

解決法(?)

起動方法Aにおいてスレッドごとにコネクションを貼りに行き、それをしばらく持つ実装になっている、と予想。すると コネクションプール数をスレッド数以上にする ことで解決できるのでは、という勘が生えた。早速設定してみよう。

database.yml
development:
  adapter: mysql2
  database: writeapp_sinatra
  host: localhost
  username: root
  password:
  encoding: utf8
  pool: 20 # 追加

起動方法Aでサーバを動かす。今度は、コネクションプール数以上のアクセスでもエラーにはならなかった。

何故起こったかを知る

取り急ぎの解決法は分かったので、今度は視点を変えて 何故設定に違いが生じたか を見ていこう。それには、両者のアプリの起動順序について細かく確認する必要がある。

起動方法A

(再掲)起動方法.A
bundle exec ruby app.rb

app.rbの末尾には run! if app_file == $0 が書かれており、これによって Sinatra::Base#run! が走るようになっている。これは公式ドキュメントで紹介されている方法である。

(再掲)app.rb
require 'sinatra/base'

# (略)

class MyApp < Sinatra::Base
  # (略)
  run! if app_file == $0
end

Sinatra::Base#run!

(#L1434)lib/sinatra/base.rb
   def run!(options = {}, &block)
        return if running?
        set options
        handler         = detect_rack_handler
        handler_name    = handler.name.gsub(/.*::/, '')
        server_settings = settings.respond_to?(:server_settings) ? settings.server_settings : {}
        server_settings.merge!(:Port => port, :Host => bind)

        begin
          start_server(handler, server_settings, handler_name, &block)
        rescue Errno::EADDRINUSE
          $stderr.puts "== Someone is already performing on port #{port}!"
          raise
        ensure
          quit!
        end
      end

start_serverの中身を見る。

(#L1504)lib/sinatra/base.rb
    def start_server(handler, server_settings, handler_name)
        handler.run(self, server_settings) do |server|
          unless handler_name =~ /cgi/i
            $stderr.puts "== Sinatra (v#{Sinatra::VERSION}) has taken the stage on #{port} for #{environment} with backup from #{handler_name}"
          end

          setup_traps
          set :running_server, server
          set :handler_name,   handler_name
          server.threaded = settings.threaded if server.respond_to? :threaded=

          yield server if block_given?
        end
      end

ここでは handler は Thin のことなので、handler.run 以降の処理は一旦 Thin に移る。サーバが準備出来たら、メッセージを出力し各種設定を行っている。

起動方法B

(再掲)起動方法.B
bundle exec rackup

rackupのコードの中身は以下のとおりである。

#!/usr/bin/env ruby

require "rack"
Rack::Server.start

Rack::Server.start が呼ばれているようなので、そのコードを読む。

(#L146)lib/rack/server.rb
    def self.start(options = nil)
      new(options).start
    end

インスタンスの start が呼ばれているので、追う。

(#L257)lib/rack/server.rb
    def start &blk
      if options[:warn]
        $-w = true
      end

      if includes = options[:include]
        $LOAD_PATH.unshift(*includes)
      end

      if library = options[:require]
        require library
      end

      if options[:debug]
        $DEBUG = true
        require 'pp'
        p options[:server]
        pp wrapped_app
        pp app
      end

      check_pid! if options[:pid]

      # Touch the wrapped app, so that the config.ru is loaded before
      # daemonization (i.e. before chdir, etc).
      wrapped_app

      daemonize_app if options[:daemonize]

      write_pid if options[:pid]

      trap(:INT) do
        if server.respond_to?(:shutdown)
          server.shutdown
        else
          exit
        end
      end

      server.run wrapped_app, options, &blk
    end

ここで server は Thin のことである。最後の server.run でサーバを起動させていることはわかるが、ここで wrapped_app とは何だろうか。

・・・この調子でまともに追っていくのと長くなってしまうので結論だけ書くと、これは config.ru から生成される、Rack::Builder.new (を、各種middlewareでラップしたもの) のことだと分かる。

つまり、どういうことか

起動方法AではSinatraが主体となって動いているが、起動方法BではSinatraはRackの1つのmiddlewareとして扱われている。また、Thin を走らせているのは誰なのか、という点が異なる。(起動方法AではSinatra, 起動方法BではRack)

もしかしたら、このとき渡されるオプションに違いがあるため、サーバの挙動が異なるのかもしれない。(要検証)
本記事ではこれ以上深追いするのはやめておく。

感想

普段意識しない部分のコードを色々読めて楽しかった(konami)
次はスレッドごとにコネクションが張られる予想の裏を取るために、Thinのソースを読んでみたい。

あわせて読みたい

Sinatra

Sinatra

Rack

第23回 Rackとは何か(1)Rackの生まれた背景:Ruby Freaks Lounge|gihyo.jp … 技術評論社

Ruby - Rack解説 - Rackの構造とRack DSL - Qiita

Thin

Thin - yet another web server