データベースの文脈でコネクションプールという用語は昔から聞くのですが、私はあまり理解できていませんでした。
アプリケーションサーバの代表的な実装の一つであるRuby on Railsで実験し、理解を深めてみました。
検証環境の構築
今回は１台の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
- リクエスト１ 成功
- リクエスト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つ目が成功しているのかわからないのですが、最初のテスト結果とだいたい同じですね。
- リクエスト１ 成功
- リクエスト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年入社 / 地味な内容を丁寧に書きたい
