Instrumenting Trailblazer Cells::Rails

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 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
end

Once 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.