column_definitions method being called before and after every single SQL statement on PostgreSQL

I am seeing this too on RC. It's a real performance problem.

I got the same problem after switching to Rails 3.

I can cofirm that I see the same problem with rc2 in production mode using Ruby 1.9.2.p0 and pg 0.9.0.

Sorry, that was supposed to be in development mode. When cache_classes = true, they only appear once.

This works as expected

User.first

User Load (0.5ms)  SELECT "users".* FROM "users" INNER JOIN "countries" 
ON "countries"."id" =  "users"."country_id" LIMIT 1

This however, does not:

User.joins(:country).first

SQL (0.6ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), 
  d.adsrc, a.attnotnull
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"countries"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum

SQL (0.7ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), 
  d.adsrc, a.attnotnull
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum

SQL (0.7ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), 
  d.adsrc, a.attnotnull
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"countries"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum

User Load (0.5ms)  SELECT "users".* FROM "users" INNER JOIN "countries" ON 
"countries"."id" = "users"."country_id" LIMIT 1

The above repeats every time I run the command on the console, not just the first time.

Guys, have you tried running the same queries in production environment? It seems that Rails is properly caching column info there and these queries don't show up anymore every time.

Sure we tried.

SQL (0.9ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"orders"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum

  SQL (2.5ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"orders"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum
  Order Load (1.1ms)  SELECT "orders".* FROM "orders" WHERE ("orders"."closed" = 'f') AND ("orders"."cancelled" = 'f')
Rendered reservations/_order.html.erb (28.3ms)
  Court Load (0.7ms)  SELECT "courts".* FROM "courts" WHERE ("courts".sport_id = 1) ORDER BY courts.number ASC
  SQL (0.8ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"items"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum

  Item Load (0.5ms)  SELECT "items".* FROM "items" WHERE ("items"."favourite" = 't')
  SQL (1.4ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"items"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum

  Item Load (1.2ms)  SELECT "items".* FROM "items" WHERE ("items"."favourite" = 'f') ORDER BY id ASC

and so on....
This is really performance issue.

I can also confirm this problem.

Yes, it seems to happen only in development but still very annoying. Some pages involving a greater number of queries takes almost 5 seconds to render!!

We diagnosed it only happens when Arel fetches columns independently of ActiveRecord. In AR table columns are memoised in @@@ActiveRecord::Base#columns@@@, so only the first invocation will trigger a database query. Arel also supports memoisation in its @@@Arel::Table#columns@@@ method, but it doesn't seem to work in some cases.

Consider this example:

> User.first
> User.last

The first query will fetch U@@@ser#columns@@@ and subsequent calls will not run it again, as expected. Let's try a different model:

> Score.first
> Score.last

Same story, Score#columns is memoised and no further calls to the database are made to fetch attributes.

The problem arises when Arel tries to reference other columns internally. Consider this query:

> User.joins(:scores)

The join is handled by Arel, not by ActiveRecord (@@@Score#columns@@@ is never called). Arel creates a new Table object to check the attributes of the scores table (by calling @@@table = Arel::Table.new(:scores)@@@) and in that call, all calls to table.columns are memoised. You'd expect that when you run @@@User.joins(:scores)@@@ again everything is returned from memory without any unnecessary database calls. This isn't the case though. Arel initialises the table again by calling @@@Arel::Table#new@@@ and previously cached columns are lost.

We diagnosed it only happens when Arel fetches columns independently of ActiveRecord. In AR table columns are memoised in ActiveRecord::Base#columns, so only the first invocation will trigger a database query. Arel also supports memoisation in its Arel::Table#columns method, but it doesn't seem to work in some cases.

Consider this example:

> User.first
> User.last

The first query will fetch User#columns and subsequent calls will not run it again, as expected. Let's try a different model:

> Score.first
> Score.last

Same story, Score#columns is memoised and no further calls to the database are made to fetch attributes.

The problem arises when Arel tries to reference other columns internally. Consider this query:

> User.joins(:scores)

The join is handled by Arel, not by ActiveRecord (Score#columns is never called). Arel creates a new Table object to check the attributes of the scores table (by calling table = Arel::Table.new(:scores)) and in that call, all calls to table.columns are memoised. You'd expect that when you run User.joins(:scores) again everything is returned from memory without any unnecessary database calls. This isn't the case though. Arel initialises the table again by calling Arel::Table#new and previously cached columns are lost.

PS. Sorry for the previous post, formatting went out of control ;)

(from [a0fc2f7b74e5637b37c66571afe7ca67069d0dda]) providing arel with column information when possible [#5392 column_definitions method being called before and after every single SQL stat... state:resolved] http://github.com/rails/rails/commit/a0fc2f7b74e5637b37c66571afe7ca...

Hello,

I'm seeing this again on Rails 3.0.4. It seems for each SQL request, a column definition request is added. (in devel mode, with cache_classes = false)

  User Load (0.4ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 1 LIMIT 1
session2observer at /Users/Jens/Sites/dor-bort/app/controllers/application_controller.rb:138)
  Continent Load (0.3ms)  SELECT "continents".* FROM "continents"
  SQL (0.6ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"continents"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum
  Thing Load (0.6ms)  SELECT "things".* FROM "things" WHERE ("things"."locateable_id" IN (1,2,3,4,5) and "things"."locateable_type" = 'Continent')
  SQL (0.7ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"things"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum
  Country Load (1.2ms)  SELECT "countries".* FROM "countries" WHERE ("countries".continent_id IN (1,2,3,4,5))
  SQL (1.0ms)   SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull
 FROM pg_attribute a LEFT JOIN pg_attrdef d
 ON a.attrelid = d.adrelid AND a.attnum = d.adnum
 WHERE a.attrelid = '"countries"'::regclass
 AND a.attnum > 0 AND NOT a.attisdropped
 ORDER BY a.attnum

I just discovered the silent-postgres gem, that deals with this problem by silencing those boilerplate lines:
https://github.com/dolzenko/silent-postgres

Well, is it really a good idea to silence these lines, or would the correct way be to prevent those requests from being made?

I'm pretty sure those requests are deliberate in development and testing environments. I think it's something to do with the fact that caching is disabled in those environments, so the postgres driver can't assume that the schema won't change. I may have assumed wrong, though. It could be worth playing around with the caching settings, to see if the queries go away.

Yes, they go away when I set config.cache_classes to true. Also, requests are much faster. So it does seem to be a caching issue.

But IMHO it's also a performance issue, even for development. My example request:

with caching enabled: Completed 200 OK in 436ms (Views: 332.1ms | ActiveRecord: 69.6ms)

without caching: Completed 200 OK in 2257ms (Views: 1146.8ms | ActiveRecord: 875.1ms)

So Rails spends more than ten times as much time with class caching enabled compared to disabled doing database queries?

私の中で、総合評価のとっても低いアバアバクロホリスタークロ銀座店。アバクロは大好きなんですけどね。一昨日の東京駅付近での打ち合わせの後、散歩がてら久々に行ってきました。そしたらビックリ！相変わらアバクロず、踊っているだけの店員さんとかもいましたが、

I am seeing this problem in Rails 3.0.6 in production mode with cache_classes=true.

It works fine for the normal rails calls, however I see these table introspection queries for all of my delayed jobs. I did, however, double check that value of cache_classes on delayed jobs is true. Any further pointers to help me investigate what is going on?