Enhancing Rails Log Output with SQL Query Count

Rails developers often faced challenges optimizing performance due to logs that lacked detailed SQL query information.

This made it difficult to identify specific performance bottlenecks, as the logs only provided general data on database interactions and view rendering times.

A recent update to the Rails framework, offers an insightful enhancement to how Rails logs SQL queries during template rendering.

This feature is particularly useful for developers who need to monitor SQL queries to optimize performance and debug issues efficiently.

Before

Prior to the implementation of this feature, Rails logs displayed basic metrics about the requests processed, including total time, view rendering time, and database interaction time. However, they lacked detailed information about the count and type of SQL queries executed.

Let’s take a code snippet to understand the behavior better

def index
  @users = User.includes(:products).where.not(products: { id: nil })

end

The typical log output for the above code looked something like this:

SQL (0.6ms)  SELECT DISTINCT "users"."id"
FROM "users"
LEFT OUTER JOIN "products" ON "products"."user_id" = "users"."id" WHERE "products"."id" IS NOT NULL ORDER BY "users"."id" ASC LIMIT ?  [["LIMIT", 1]]

SQL (0.1ms) SELECT
  "users"."id" AS t0_r0,
  "users"."name" AS t0_r1,
  "products"."id" AS t1_r0,
  "products"."price" AS t1_r4
  FROM "users"
  LEFT OUTER JOIN "products" ON "products"."user_id" = "users"."id"
  WHERE "products"."id" IS NOT NULL AND "users"."id" = ? ORDER BY "users"."id" ASC  [["id", 1]]

Completed 200 OK in 15ms (Views: 9.5ms | ActiveRecord: 1.7ms | Allocations: 43356)

After

With the new change, Rails logs have become significantly more informative by including the count of SQL queries directly in the log output.

This addition helps developers quickly assess whether their code modifications have led to an increase or decrease in database queries, helping in performance optimization and debugging.

The enhanced log output for the same code will look like this:

SQL (0.6ms)  SELECT DISTINCT "users"."id"
FROM "users"
LEFT OUTER JOIN "products" ON "products"."user_id" = "users"."id" WHERE "products"."id" IS NOT NULL ORDER BY "users"."id" ASC LIMIT ?  [["LIMIT", 1]]

SQL (0.1ms) SELECT
  "users"."id" AS t0_r0,
  "users"."name" AS t0_r1,
  "products"."id" AS t1_r0,
  "products"."price" AS t1_r4
  FROM "users"
  LEFT OUTER JOIN "products" ON "products"."user_id" = "users"."id"
  WHERE "products"."id" IS NOT NULL AND "users"."id" = ? ORDER BY "users"."id" ASC  [["id", 1]]

Completed 200 OK in 20ms (Views: 9.5ms | ActiveRecord: 1.7ms (2 queries, 0 cached) | Allocations: 25120)

This output not only shows the total time spent on ActiveRecord but also breaks down the number of queries executed and how many of them were served from the cache.

To know more about this feature, please refer to this PR