Rails logs provide useful information indicating where queries are being fired from along with any custom logging information. We can utilise the query logs indicating line numbers to identify performance bottlenecks.

There are quite a few gems available to find out performance bottlenecks. Bullet helps identify N+1 queries in the application. It also help with removing unused eager loading of associations. While such gems help identify performance bottlenecks, sometimes it’s rather difficult to identify bottlenecks if the queries being fired are not N+1 queries, but they are being called multiple times from different workflows.

Rails provides a configuration option verbose_query_logs on ActiveRecord::Base. It is enabled by default in applications > Rails 5.2 It gives query logs with line numbers firing the query in Rails logs.

Below is the sample log generated in log file.

  Post Load (0.2ms)  SELECT "posts".* FROM "posts"
  ↳ app/models/post.rb:5
  Comment Load (0.1ms)  SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = ?  [["post_id", 1]]
  ↳ app/models/post.rb:6
  Comment Load (0.1ms)  SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = ?  [["post_id", 2]]
  ↳ app/models/post.rb:6
  Comment Load (0.1ms)  SELECT "comments".* FROM "comments" WHERE "comments"."post_id" = ?  [["post_id", 3]]
  ↳ app/models/post.rb:6

In this case, it’s easier to identify the source of the problem. i.e. we need to look at app/models.post.rb#6. We can add eager loading to resolve this particular issue.

It can be quite overwhelming to find out which parts of our code are causing bottlenecks.

In such cases, we can use a simple bash command given below to find out which lines are getting called most number of times.

 cat log/development.log | sort | uniq -c | sort -n

Assuming we are looking in log files of development environment. The line above lists down log lines in sorted manner with line numbers which are logged most number of times at the last with count showing how many times it’s being called.

Posting a sample output of the command given above.

   5170   User Load (0.1ms)  SELECT "users".* FROM "users" WHERE "users"."type" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["type", "SuperAdmin"], ["LIMIT", 1]]
   5276   Product Load (0.1ms)  SELECT "products".* FROM "products" WHERE "products"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
   5981   Portal Load (0.1ms)  SELECT "portals".* FROM "portals" WHERE "portals"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
   9775   Cost Load (0.1ms)  SELECT "costs".* FROM "costs" WHERE "costs"."id" = $1 LIMIT $2  [["id", 19], ["LIMIT", 1]]
  10072   Cost Load (0.1ms)  SELECT "costs".* FROM "costs" WHERE "costs"."id" = $1 LIMIT $2  [["id", 18], ["LIMIT", 1]]

As we can see it clearly states which query is being fired huge number of times in the application. We can utilize this information effectively to find out which lines are hogging our application.

Often times, we need to optimize performance of certain parts / workflows of our application. In such case, we can respwan the log file.

rm log/development.log
touch log/development.log

Execute the workflow by restarting rails server and execute the command given above to find out issues in a particular session.