Rails Ruby on Rails → 3.0.2

Comments and changes to this ticket

• You flagged this item as spam.
  

  Brandon Keene August 26th, 2010 @ 03:27 PM

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

• You flagged this item as spam.
  

  Szymon Nowak August 27th, 2010 @ 08:30 AM

  I got the same problem after switching to Rails 3.

• You flagged this item as spam.
  

  Tor Erik August 27th, 2010 @ 09:38 AM

  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.

• You flagged this item as spam.
  

  Tor Erik August 27th, 2010 @ 10:16 AM

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

• You flagged this item as spam.
  

  Tor Erik August 27th, 2010 @ 10:51 AM

  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.

• You flagged this item as spam.
  

  Szymon Nowak August 27th, 2010 @ 01:28 PM

  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.

• You flagged this item as spam.
  

  MikZ September 2nd, 2010 @ 02:58 AM

  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.

• You flagged this item as spam.
  

  Rodrigo Kochenburger September 9th, 2010 @ 06:18 PM

  I can also confirm this problem.

• You flagged this item as spam.
  

  Rodrigo Kochenburger September 9th, 2010 @ 06:25 PM

  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!!

• You flagged this item as spam.
  

  Mateusz Drożdżyński September 21st, 2010 @ 10:37 AM

  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.

• You flagged this item as spam.
  

  Mateusz Drożdżyński September 21st, 2010 @ 10:40 AM

  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 ;)

• 

  José Valim September 21st, 2010 @ 11:04 AM

  • Milestone cleared.
  • State changed from “new” to “open”
  • Assigned user set to “Aaron Patterson”
  • Importance changed from “” to “High”

  Aaron, could you please take a look? Internet hugs!

• 

  Repository September 21st, 2010 @ 09:54 PM

  • State changed from “open” to “resolved”

  (from [96bd936b64ae06d4c38e8de862521e22d7c809b9]) providing arel with column information when possible [#5392 state:resolved] http://github.com/rails/rails/commit/96bd936b64ae06d4c38e8de862521e...

• 

  Repository September 21st, 2010 @ 09:54 PM

  (from [a0fc2f7b74e5637b37c66571afe7ca67069d0dda]) providing arel with column information when possible [#5392 state:resolved] http://github.com/rails/rails/commit/a0fc2f7b74e5637b37c66571afe7ca...

• 

  Jeremy Kemper October 15th, 2010 @ 11:02 PM

  • Milestone set to “3.0.2”

  [bulk edit]

• You flagged this item as spam.
  

  Jens February 27th, 2011 @ 02:34 PM

  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
  

• You flagged this item as spam.
  

  Paul Gideon Dann March 1st, 2011 @ 11:58 AM

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

• You flagged this item as spam.
  

  Jens March 2nd, 2011 @ 06:09 AM

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

• You flagged this item as spam.
  

  Paul Gideon Dann March 2nd, 2011 @ 09:27 AM

  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.

• You flagged this item as spam.
  

  Jens March 2nd, 2011 @ 08:06 PM

  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?

• You flagged this item as spam.
  

  af001 May 5th, 2011 @ 03:01 AM

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

• You flagged this item as spam.
  

  quarterdome May 20th, 2011 @ 06:45 PM

  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?