Railsを動かして理解するDBコネクションプール

記事タイトルとURLをコピーする

データベースの文脈でコネクションプールという用語は昔から聞くのですが、私はあまり理解できていませんでした。
アプリケーションサーバの代表的な実装の一つであるRuby on Railsで実験し、理解を深めてみました。

検証環境の構築

今回は1台のEC2インスタンスを使います。 アプリ(Rails)とDB(MariaDB)は、同じEC2インスタンス(Amazon Linux 2)で動かします。

検証用Railsの準備

Railsのインストールまで

おそらく環境依存の話はないと思うのですが、今回は Ruby on Rails 6をAmazon Linux 2で動かすの手順でインストールしました。

DB接続設定

Railsのデフォルトではsqlite3を使うようになっていますが、今回はMariaDBを使うようにします。

mysql2(gem)のインストール

Gemfileに以下を追記します。

gem 'mysql2'
[sample]$ bundle install
[sample]$ gem pristine mysql2 --version 0.5.3

config/database.yml

まずはこんな感じの接続設定にしてみました。
poolは2と少なめにしてみました。

default: &default
  adapter: mysql2
  encoding: utf8
  reconnect: false
  pool: 2
  username: testuser
  password: **********
  host: 127.0.0.1
  timeout: 5000

development:
  <<: *default
  database: dev

MariaDBの準備

MariaDBのインストール

$ sudo yum install mariadb-server
$ sudo systemctl enable mariadb
$ sudo systemctl start mariadb

DBのユーザー作成

$ mysql -uroot -p
Enter password:

MariaDB [(none)]> GRANT ALL PRIVILEGES ON *.* TO 'testuser'@'localhost'  IDENTIFIED BY '**********';
MariaDB [(none)]> FLUSH PRIVILEGES;

DB作成

今回は丁寧に工夫して作った時の動作ではなく、「なんとなく普通に動かした時の動作」を知りたかったので、scaffoldで作ってみました。

[sample]$ rake db:create

[sample]$ rails g scaffold Employee name:string grade:integer
[sample]$ rake db:migrate

テスト

rails server

[sample]$ rails s -b 0.0.0.0 -p 3333
=> Booting Puma
=> Rails 6.0.2.1 application starting in development
=> Run `rails server --help` for more startup options
Puma starting in single mode...
* Version 4.3.1 (ruby 2.6.3-p62), codename: Mysterious Traveller
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3333
Use Ctrl-C to stop
$ sudo netstat -lanput | grep 3306
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      26057/mysqld

この時点では、TCP:3306の接続は待ち受け用に1つ見えるだけでした。

なるほど、Railsガイド:データベース接続をプールするには、 最初はデータベース接続のプールは空で、必要に応じて追加接続が作成され、接続プールの上限に達するまで接続が追加されます。 と書いてありました。 アクセス無いと増えないんですね。

DBアクセスの発生するページにブラウザでアクセス

http://x.x.x.x:3333/employees/ にアクセスしてみます。
コントローラのコード(app/controllers/employees_controller.rb)は以下のようになっています。
Employee.all の部分でDBアクセスが発生します。

class EmployeesController < ApplicationController
  before_action :set_employee, only: [:show, :edit, :update, :destroy]

  # GET /employees
  # GET /employees.json
  def index
    @employees = Employee.all
  end

コンソールのログを見ると、SQL(SELECT文)が発行されているのがわかります。

Started GET "/employees/" for 58.93.31.171 at 2020-01-22 23:44:10 +0000
Cannot render console from 58.93.31.171! Allowed networks: 127.0.0.0/127.255.255.255, ::1
Processing by EmployeesController#index as HTML
  Rendering employees/index.html.erb within layouts/application
  Employee Load (0.3ms)  SELECT `employees`.* FROM `employees`
  ↳ app/views/employees/index.html.erb:15
  Rendered employees/index.html.erb within layouts/application (Duration: 1.4ms | Allocations: 776)
[Webpacker] Everything's up-to-date. Nothing to do
Completed 200 OK in 5ms (Views: 4.5ms | ActiveRecord: 0.3ms | Allocations: 4107)

TCP接続が2つ増えてますね。
1アクセスなのに2つな理由は、DB側(mysqld)とアプリ側(puma)で1つずつ必要だからです。

$ sudo netstat -lanput | grep 3306
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      26057/mysqld
tcp        0      0 127.0.0.1:3306          127.0.0.1:46452         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:46452         127.0.0.1:3306          ESTABLISHED 2858/puma 4.3.1 (tc

ブラウザのアクセスは即座にレスポンスがきましたが、その後もこのアプリとDB間の接続は残っています。
コネクションを1つプールしているということなんでしょう。

次にブラウザのリロードボタンを連打したり、他のブラウザや端末からアクセスしてみました。
結果、アプリとDBの接続は増えも減りもしませんでした。
これはリクエスト処理が瞬間的に完了してしまうためと思われます。

時間のかかる処理を試す

コントローラーの処理で時間がかる場合

30秒間sleepする処理を入れてみました。

class EmployeesController < ApplicationController
  before_action :set_employee, only: [:show, :edit, :update, :destroy]

  # GET /employees
  # GET /employees.json
  def index
    @employees = Employee.all
    sleep 30
  end

ブラウザの複数タブから並列にリクエストを出してみると、確かにconfig/database.yml で指定したpool 2 が効いているようです。
2セットのTCP接続が上限となっています。

$ sudo netstat -lanput | grep 3306
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      26057/mysqld
tcp        0      0 127.0.0.1:46504         127.0.0.1:3306          ESTABLISHED 3233/puma 4.3.1 (tc
tcp        0      0 127.0.0.1:3306          127.0.0.1:46510         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:3306          127.0.0.1:46504         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:46510         127.0.0.1:3306          ESTABLISHED 3233/puma 4.3.1 (tc
  • リクエスト1 成功
  • リクエスト2 成功
  • リクエスト3 成功
  • リクエスト4 all pooled connections were in use
  • リクエスト5 all pooled connections were in use
  • リクエスト6 all pooled connections were in use
エラーログ(コンソール)
ActiveRecord::ConnectionTimeoutError (could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use):
エラー画面(ブラウザ)

poolが2しかないのに、3つ目のリクエストが成功したのが意外でした。
timeout: 5000などのなんらかのタイムアウト値が関係している可能性も考えられます。
詳細は理解できていないですが、pool数は同時アクセスに重要なようです。

ただ、実際のDBへのリクエストはsleepの前の @employees = Employee.all だけな気もするので、その後はDBコネクションを解放するかと予想したのですが、コントローラー全体の処理が終わるまで(ブラウザへレンダリングするまで?)維持する感じですね。

ここでpoolを5にしてみて同じアクセスをすると、全てのリクエストが成功し、下記のような接続になりました。

$ sudo netstat -lanput | grep 3306
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      26057/mysqld
tcp        0      0 127.0.0.1:3306          127.0.0.1:46546         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:46548         127.0.0.1:3306          ESTABLISHED 3520/puma 4.3.1 (tc
tcp        0      0 127.0.0.1:3306          127.0.0.1:46542         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:3306          127.0.0.1:46552         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:46552         127.0.0.1:3306          ESTABLISHED 3520/puma 4.3.1 (tc
tcp        0      0 127.0.0.1:46546         127.0.0.1:3306          ESTABLISHED 3520/puma 4.3.1 (tc
tcp        0      0 127.0.0.1:46544         127.0.0.1:3306          ESTABLISHED 3520/puma 4.3.1 (tc
tcp        0      0 127.0.0.1:46542         127.0.0.1:3306          ESTABLISHED 3520/puma 4.3.1 (tc
tcp        0      0 127.0.0.1:3306          127.0.0.1:46544         ESTABLISHED 26057/mysqld
tcp        0      0 127.0.0.1:3306          127.0.0.1:46548         ESTABLISHED 26057/mysqld

DBトランザクションで時間がかかる場合

先ほどはController内に単純にsleepを入れただけでしたが、少しだけ変えて、DBトランザクション内でsleepしてみました。

class EmployeesController < ApplicationController
  before_action :set_employee, only: [:show, :edit, :update, :destroy]

  # GET /employees
  # GET /employees.json
  def index
    ActiveRecord::Base.transaction do
        @employees = Employee.all
        sleep 30
    end
  end

結果は以下の通りです。
なぜ3つ目が失敗し、4つ目が成功しているのかわからないのですが、最初のテスト結果とだいたい同じですね。

  • リクエスト1 成功
  • リクエスト2 成功
  • リクエスト3 all pooled connections were in use
  • リクエスト4 成功
  • リクエスト5 all pooled connections were in use
  • リクエスト6 all pooled connections were in use

まとめ

  • Railsは、DBへのリクエストにコネクションプールを高速に使い回すので、軽い処理なら少ないpool数でも同時リクエスト可能。
  • DBへのアクセスを必要とする処理は、概ねpool数だけ並列処理ができる。

色々試しましたが、結果的には、Railsガイド:データベース接続をプールするの内容を確認してみたという感じになりました。

細かいところはさておき、DBコネクションの基本は理解できました。

なお、私は普段はRailsエンジニアでもデベロッパーでも無いので、何か色々間違っていたらゴメンナサイ。

追記

弊社メンバーからコメントをいただきました。

なるほどですね〜。
コネクションプール作成のタイミングとSQL実行のタイミングについて、確認してみました。

Rails起動直後

sleep 30を入れた状態でRailsを起動しました。
前述したように、この時点ではTCP接続はありません。

$ rails s -b 0.0.0.0 -p 3333
=> Booting Puma
=> Rails 6.0.2.1 application starting in development
=> Run `rails server --help` for more startup options
Puma starting in single mode...
* Version 4.3.1 (ruby 2.6.3-p62), codename: Mysterious Traveller
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3333
Use Ctrl-C to stop

ブラウザでアクセス直後

初回アクセス時のみ、 SELECT schema_migrations が実行されます。
これが何か調べてないのですが、2回目のアクセスからは発生しませんでした。
私がsleepを入れたindexメソッドとは別の場所にコードが記載されているものと思われます。
そしてこれが実行されたためだと思いますが、この時点でコネクションプールが1つ作成されます。

Started GET "/employees" for 219.100.28.149 at 2020-01-24 00:09:20 +0000
Cannot render console from 219.100.28.149! Allowed networks: 127.0.0.0/127.255.255.255, ::1
   (0.3ms)  SET NAMES utf8,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.sql_auto_is_null = 0, @@SESSION.wait_timeout = 2147483
   (0.2ms)  SELECT `schema_migrations`.`version` FROM `schema_migrations` ORDER BY `schema_migrations`.`version` ASC
Processing by EmployeesController#index as HTML
$ netstat -lanput | grep 3306
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      -
tcp        0      0 127.0.0.1:3306          127.0.0.1:45642         ESTABLISHED -
tcp        0      0 127.0.0.1:45642         127.0.0.1:3306          ESTABLISHED 3131/puma 4.3.1 (tc

レンダリング時

長い処理(今回はsleepですが)の時間も経過し、ブラウザに表示される段階になって、 SELECT employees が実行されてました。

  Rendering employees/index.html.erb within layouts/application
  Employee Load (0.3ms)  SELECT `employees`.* FROM `employees`
  ↳ app/views/employees/index.html.erb:15
  Rendered employees/index.html.erb within layouts/application (Duration: 7.8ms | Allocations: 4671)
[Webpacker] Everything's up-to-date. Nothing to do
Completed 200 OK in 30027ms (Views: 14.4ms | ActiveRecord: 1.2ms | Allocations: 15853)

渡辺 信秀(記事一覧)

2017年入社 / 地味な内容を丁寧に書きたい