Search code examples
ruby-on-railsrubymacospostgresqlpg

Rails with PostgreSQL reconnecting multiple times per request

I recently encountered a problem where Rails is dropping connections to my PostgreSQL causing multiple reconnects per request, significantly slowing down requests. I am currently running everything local on Mac OS X with the following environment:

  • Mac OS X 10.8 (Mountain Lion)
  • Pow
  • NginX (ssl unwrapping - same app reconnect behavior even without this enabled)
  • PostgreSQL 9.2.2 via Homebrew
  • Rails 3.2.11

Here is my database.yml: (database and username redacted)

development:
  adapter: postgresql
  encoding: unicode
  database: <database>
  pool: 5
  username: <user>
  password:

This is the output from development.log during a typical request: (specific models and renders redacted)

Connecting to database specified by database.yml


Started GET "/" for 127.0.0.1 at 2013-02-05 12:25:38 -0800
Processing by HomeController#index as HTML
  ... <app performs model loads and render calls>
Completed 200 OK in 314ms (Views: 196.0ms | ActiveRecord: 60.9ms)
Connecting to database specified by database.yml
Connecting to database specified by database.yml

I also enabled statement logging in Postgres to get better insight into what exactly was happening on the database side during a given request. Here is the output from postgresql-<date>.log: (queries specific to my app redacted)

LOG:  connection received: host=[local]
LOG:  connection authorized: user=<user> database=<database>
LOG:  statement: set client_encoding to 'UTF8'
LOG:  statement: set client_encoding to 'unicode'
LOG:  statement: SHOW client_min_messages
LOG:  statement: SET client_min_messages TO 'panic'
LOG:  statement: SET standard_conforming_strings = on
LOG:  statement: SET client_min_messages TO 'notice'
LOG:  statement: SET time zone 'UTC'
LOG:  statement: SHOW TIME ZONE
LOG:  statement: SELECT 1
LOG:  statement: SELECT 1
    ... <app makes queries for request>
LOG:  disconnection: session time: 0:00:01.346 user=<user> database=<database> host=[local]
LOG:  connection received: host=[local]
LOG:  connection authorized: user=<user> database=<database>
LOG:  statement: set client_encoding to 'UTF8'
LOG:  statement: set client_encoding to 'unicode'
LOG:  statement: SHOW client_min_messages
LOG:  statement: SET client_min_messages TO 'panic'
LOG:  statement: SET standard_conforming_strings = on
LOG:  statement: SET client_min_messages TO 'notice'
LOG:  statement: SET time zone 'UTC'
LOG:  statement: SHOW TIME ZONE
LOG:  statement: SELECT 1
LOG:  connection received: host=[local]
LOG:  connection authorized: user=<user> database=<database>
LOG:  statement: set client_encoding to 'UTF8'
LOG:  statement: set client_encoding to 'unicode'
LOG:  statement: SHOW client_min_messages
LOG:  statement: SET client_min_messages TO 'panic'
LOG:  statement: SET standard_conforming_strings = on
LOG:  statement: SET client_min_messages TO 'notice'
LOG:  statement: SET time zone 'UTC'
LOG:  statement: SHOW TIME ZONE
LOG:  statement: SELECT 1
LOG:  statement: SELECT 1
LOG:  statement: SELECT 1
LOG:  disconnection: session time: 0:00:00.750 user=<user> database=<database> host=[local]
LOG:  disconnection: session time: 0:00:00.733 user=<user> database=<database> host=[local]

I'm happy to update with relevant configs or log outputs for command calls. Also, why all the SELECT 1 calls? What is their purpose?

Thanks!

Solution

  • The answer is to upgrade PostgreSQL to a newer version. I just upgraded to 9.2.4 from 9.2.2 as used in the original question and the problem went away entirely, with expected performance characteristics returning to my development application.