In a recent project i am involved in, i had to perform some optimization regarding the overall application response time, and it happens this application is using Trailblazer Cells::Rails, or better known as cells-rails. I have started to dig into the templates in an attempt to apply some Russian doll caching, and at a first i have been a bit puzzled about the fact that my template was rendered inside the layout in about 227 ms, considering it was a fairly slim template.
Opening the view template in question, i have seen that it had 14 lines of code, and around 4 of those were part of an each statement.
<% SomeModel.published.for_scope(:homepage, organization: current_organization).each do |content_block| %> <% next unless content_block.manifest %> <%= cell content_block.manifest.cell, content_block %> <% end %>
I was intrigued about the fact that a cell helper appeared in my calls, yet, i could see how much time it was actually consumed in that cell. Diving into the code, I have seen the method was part of the rails-cells gem, which was part of my codebase.
Inspired by the ActionView’s instrumentation system, I have started to write a simple library, which in the end made use of the ActiveSupport::Notifications
module to display all the calls that were made to that cell helper functions.
module Cell module ViewModelInstrumenter def call(*) identifier = self.class.name.sub(/Cell$/, "").underscore instrument(:cell, identifier: identifier) do |_payload| Rails.logger.info("Start rendering #{identifier}") content = super Rails.logger.info("Finished rendering #{identifier}") content end end private def instrument(name, **options) ActiveSupport::Notifications.instrument("render_#{name}.action_view", options) do |payload| yield payload end end end endOnce i had the instrumenter code in place, i needed to make sure it was actually called, therefore i needed to update my initializer to make use of the new module.
::Cell::RailsExtensions
::ViewModel.send(:include, ::Cell::ViewModelInstrumenter)
Once i had the call method in place, i needed also to make sure the events triggered are caught. Altering another initializer was the key, therefore, i have dropped the following config in it.
ActiveSupport::Notifications.subscribe "render_cell.action_view" do |name, started, finished, unique_id, data|
event = ActiveSupport::Notifications::Event.new(name, started, finished, unique_id, data)
message = "Rendered cell #{event.payload[:identifier]} (#{event.duration.round(1)}ms)"
Rails.logger.info(message)
end
After restarting the application, i could see in my logs entries like:
app | I, [2020-09-20T20:57:21.368665 #4696] INFO -- : Start rendering /author app | I, [2020-09-20T20:57:21.379692 #4696] INFO -- : Start rendering /follow_button app | I, [2020-09-20T20:57:21.385146 #4696] INFO -- : Finished rendering /follow_button
app | I, [2020-09-20T20:57:21.385226 #4696] INFO -- : Rendered cell /follow_button (5.5ms) app | I, [2020-09-20T20:57:21.385369 #4696] INFO -- : Finished rendering /author app | I, [2020-09-20T20:57:21.385409 #4696] INFO -- : Rendered cell /author (16.7ms)
Now, having this kind of logging, helps me optimize and improve my existing code.