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?

Margy

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. – Gneiss

Thx for the edit. The thing is, we never call this explicitly. Perhaps the side effect of something. Any idea how to back trace? – Margy

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" – Denys

Oops, sorry typo. Should be 1.5 s – Margy

Is in your production environment cache_classes=true? Which Rails version do you use? – Genovevagenre

you might want to try github.com/MiniProfiler/rack-mini-profiler and github.com/flyerhzm/bullet in development, maybe it gives some insights – Gastrin

@Genovevagenre yes, we have that. Rails 4.0.9 – Margy

@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)? – Genovevagenre

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. – Boulware

Could be useful to add something like 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. – Pimentel

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 : postgresql-archive.org/… – Hydantoin

Answer 1

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.

Aussie

Answer 2

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.

Yelmene

Answer 3

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.

Femineity