CODEWITHSUNDEEP
ruby-on-railsrubypostgresql
Mark
Mark

Reputation: 6455

Rails - getting access to DB query times in production log

I'm trying to figure out what is causing a poor time to first byte for a site written in rails, and can see in the production logs that some database queries are taking over a second:

Started GET "/" for 46.38.178.9 at 2018-01-07 11:50:45 +0000
I, [2018-01-07T11:50:45.044625 #25767]  INFO -- : Processing by HomeController#index as */*
I, [2018-01-07T11:50:45.058432 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.6ms)
I, [2018-01-07T11:50:45.059066 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.059719 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.060345 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.061015 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.6ms)
I, [2018-01-07T11:50:45.061626 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.062260 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.062873 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.063504 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.064115 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.064763 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.065389 #25767]  INFO -- :   Rendered shared/analytics/_impression.js.erb (0.5ms)
I, [2018-01-07T11:50:45.065468 #25767]  INFO -- :   Rendered shared/analytics/_impressions_multiple.js.erb (7.8ms)
I, [2018-01-07T11:50:45.073834 #25767]  INFO -- :   Rendered shared/_review_banners.html.erb (6.2ms)
I, [2018-01-07T11:50:45.081136 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (7.0ms)
I, [2018-01-07T11:50:45.087936 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.6ms)
I, [2018-01-07T11:50:45.094084 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (5.9ms)
I, [2018-01-07T11:50:45.100248 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.0ms)
I, [2018-01-07T11:50:45.107051 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.6ms)
I, [2018-01-07T11:50:45.113837 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.6ms)
I, [2018-01-07T11:50:45.120657 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.6ms)
I, [2018-01-07T11:50:45.128780 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (7.9ms)
I, [2018-01-07T11:50:45.135850 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.9ms)
I, [2018-01-07T11:50:45.141214 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (5.2ms)
I, [2018-01-07T11:50:45.148157 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (6.8ms)
I, [2018-01-07T11:50:45.153795 #25767]  INFO -- :   Rendered shared/_tour_card.html.erb (5.3ms)
I, [2018-01-07T11:50:45.153877 #25767]  INFO -- :   Rendered home/_best_sellers.html.erb (79.9ms)
I, [2018-01-07T11:50:45.154567 #25767]  INFO -- :   Rendered home/_categories.html.erb (0.6ms)
I, [2018-01-07T11:50:45.155882 #25767]  INFO -- :   Rendered shared/_testimonials.html.erb (0.3ms)
I, [2018-01-07T11:50:45.156036 #25767]  INFO -- :   Rendered shared/usp/_generic.html.erb (0.0ms)
I, [2018-01-07T11:50:45.156200 #25767]  INFO -- :   Rendered home/index.html.erb within layouts/application (110.0ms)
I, [2018-01-07T11:50:46.299424 #25767]  INFO -- :   Rendered shared/_tour_links.html.erb (12.0ms)
I, [2018-01-07T11:50:46.299538 #25767]  INFO -- :   Rendered shared/_header.html.erb (1140.6ms)
I, [2018-01-07T11:50:46.313482 #25767]  INFO -- :   Rendered shared/_tour_links.html.erb (13.5ms)
I, [2018-01-07T11:50:46.318732 #25767]  INFO -- :   Rendered shared/_footer.html.erb (19.0ms)
I, [2018-01-07T11:50:46.319224 #25767]  INFO -- : Completed 200 OK in 1275ms (Views: 135.7ms | ActiveRecord: 1137.7ms | Solr: 0.0ms)

Is there any way for me to add the sql queries to the production log file as they are shown in the development console? i.e.

FooterLink Load (1.1ms)  SELECT "navigation_links".* FROM "navigation_links" WHERE "navigation_links"."location" = $1 AND "navigation_links"."column" = $2  [["location", 0], ["column", 3]]

Or alternatively is there any way to 'view them live' like you do when making queries in development? All I can find after googling is how to change where the log is stored and the STDOUT but nothing on query logging.

Thanks in advance

Upvotes: 1

Views: 427

Answers (1)

Daniel
Daniel

Reputation: 899

Just change you log level. You can change it to debug mode. http://guides.rubyonrails.org/debugging_rails_applications.html#log-levels

Upvotes: 1

Related Questions