How to fix a slow implicit query on pg_attribute table in Rails

Question

In our production environment, we noticed frequent spikes (~every 1 hour) in our Rails application. Digging deeper, it's due to the following query which cumulatively runs in >1.5 s (called 100x) in a single HTTP request.

SELECT a.attname, format_type(a.atttypid, a.atttypmod), pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod FROM pg_attribute a
LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = ?::regclass AND a.attnum > ? AND NOT a.attisdropped 
ORDER BY a.attnum

We don't have code calling that table explicitly but seems it's called by Rails to figure out the attributes for each model. "Unexpected SQL queries to Postgres database on Rails/Heroku" is related.

But shouldn't it be called non-repetitively by Rails?

How do we speed this up?

Have you identified where this us called? If so you could probably figure out how to cache this response in memcache or the like and cut down on the frequency. I would not eliminate any core rails call all together but caching with a ttl might help. Just a thought. — engineersmnky, Aug 05 '16 at 00:37
Thx for the edit. The thing is, we never call this explicitly. Perhaps the side effect of something. Any idea how to back trace? — Pahlevi Fikri Auliya, Aug 05 '16 at 01:37
`which runs in >1.5 ms` I wouldn't call that *slow* `...and is called 100x` but I wouldn't call il hundred times repeatedly. This looks like a RoR "feature" — joop, Aug 05 '16 at 10:48
Is in your production environment `cache_classes=true`? Which Rails version do you use? — slowjack2k, Aug 10 '16 at 07:57
you might want to try https://github.com/MiniProfiler/rack-mini-profiler and https://github.com/flyerhzm/bullet in development, maybe it gives some insights — jethroo, Aug 11 '16 at 19:26
@PahleviFikriAuliya Maybe the issue is outsite Rails. Do you kill rails processes every hour? Mabye do you use unicorn with worker killer, or a monitoring system that watches memory consumption? What server do you use (puma, thin, unicorn)? Edit: How many models do you have (the ~100)? — slowjack2k, Aug 12 '16 at 07:31
It would be useful if I could see the full log where this query occurs. Is it during some controller action call? Is it in a random controller action or in some particular one? Can you add debug statements in such controller action (on every line), to detect which line exactly causes this side effect? That "Unexpected SQL queries to Postgres database on Rails/Heroku" gives some insight, but if you want to dig the actual reason, you have to be more descriptive. — , Aug 14 '16 at 07:41
Could be useful to add something like https://www.skylight.io/ or newrelic to better monitor calls in your code. This can point out to the real reason why your code is slow at some points in time. When reading "Unexpected SQL queries to Postgres database on Rails/Heroku" is also states that table structure is cached in production env. So I would also check that nobody changed the ENV parameter to development. — Stephane Paquet, Jul 23 '17 at 12:05
Best option you have is to do EXPLAIN ANALYZE and share here. All Postgres system catalogs are just tables and this query may just be not effective. Personally I have encountered issues with INFORMATION_SCHEMA tables. Some of them are actually implemented as views (just sql). One of the last ones : http://www.postgresql-archive.org/Incredibly-slow-queries-on-information-schema-constraint-column-usage-td6000680.html — Zorg, May 22 '18 at 03:07

score 3 · Accepted Answer · answered Jul 20 '18 at 18:23

In production, each Rails process will run that query once for each table/model it encounters. That's once per rails s, not per request: if you're seeing it repeatedly, I'd investigate whether your processes are being restarted frequently for some reason.

To eliminate those runtime queries entirely, you can generate a schema cache file on your server:

RAILS_ENV=production rails db:schema:cache:dump

(Rails 4: RAILS_ENV=production bin/rake db:schema:cache:dump)

That command will perform the queries immediately, and then write their results to a cache file, which future Rails processes will directly load instead of inspecting the database. Naturally, you'll then need to regenerate the cache after any future database schema changes.

score 0 · Answer 2 · answered Aug 16 '17 at 08:57

I have not experienced this issue in any Rails application I've worked so far. I think your solution is to add active-record-query-trace to your project and check, what is triggering this query.

At work I use this setup:

# Gemfile
group :test, :development do
  gem "active-record-query-trace"
end

# config/initializers/ar_tracer.rb
if ENV.has_key?("AR_TRACER") && defined? ActiveRecordQueryTrace
  ActiveRecordQueryTrace.enabled = true
  ActiveRecordQueryTrace.lines = 20 # you may want to increase if not enough
end

Then simply start your rails server like this: AR_TRACER=1 bundle exec rails s.

score 0 · Answer 3 · answered Oct 09 '18 at 18:36

As recommended in this issue comment, you can add it to your Procfile:

web: rails db:schema:cache:dump && rails s ...

If you're on Heroku, you cannot simply run it using heroku run ... because the schema dump is only generated on a per-server basis and the command will run on a one-off dyno, which will disappear immediately after the command is run. You need to make sure it runs on each server as it boots.

How to fix a slow implicit query on pg_attribute table in Rails

3 Answers3

Linked