Create top-level profile timing nodes for multiple template renders

lib/liquid/profiler.rb

@@ -46,98 +46,92 @@ module Liquid
     include Enumerable
 
     class Timing
-      attr_reader :code, :partial, :line_number, :children, :total_time, :self_time
+      attr_reader :code, :template_name, :line_number, :children
+      attr_accessor :total_time
       alias_method :render_time, :total_time
+      alias_method :partial, :template_name
 
-      def initialize(node, template_name)
+      def initialize(code: nil, template_name: nil, line_number: nil)
-        @code        = node.respond_to?(:raw) ? node.raw : node
+        @code = code
-        @partial     = template_name
+        @template_name = template_name
-        @line_number = node.respond_to?(:line_number) ? node.line_number : nil
+        @line_number = line_number
         @children = []
       end
 
-      def self.start(node, template_name)
+      def self_time
-        new(node, template_name).tap(&:start)
+        @self_time ||= begin
-      end
+          total_children_time = 0.0
-
-      def start
-        @start_time = monotonic_time
-      end
-
-      def finish
-        @total_time = monotonic_time - @start_time
-
-        if @children.empty?
-          @self_time = @total_time
-        else
-          total_children_time = 0
           @children.each do |child|
             total_children_time += child.total_time
           end
-          @self_time = @total_time - total_children_time
+          @total_time - total_children_time
+        end
       end
     end
 
-      private
+    attr_reader :total_time
-
+    alias_method :total_render_time, :total_time
-      def monotonic_time
-        Process.clock_gettime(Process::CLOCK_MONOTONIC)
-      end
-    end
-
-    attr_reader :total_render_time
 
     def initialize
-      @root_timing  = Timing.new("", nil)
+      @root_children = []
-      @timing_stack = [@root_timing]
+      @current_children = nil
-      @render_start_at = nil
+      @total_time = 0.0
-      @total_render_time = 0.0
     end
 
-    def profile
+    def profile(template_name, &block)
-      return yield if @render_start_at
+      # nested renders are done from a tag that already has a timing node
-      started_at = monotonic_time
+      return yield if @current_children
+
+      root_children = @root_children
+      render_idx = root_children.length
       begin
-        @started_at = started_at
+        @current_children = root_children
-        yield
+        profile_node(template_name, &block)
       ensure
-        @started_at = nil
+        @current_children = nil
-        @total_render_time += monotonic_time - started_at
+        if (timing = root_children[render_idx])
+          @total_time += timing.total_time
+        end
+      end
+    end
+
+    def children
+      children = @root_children
+      if children.length == 1
+        children.first.children
+      else
+        children
       end
     end
 
     def each(&block)
-      @root_timing.children.each(&block)
+      children.each(&block)
     end
 
     def [](idx)
-      @root_timing.children[idx]
+      children[idx]
     end
 
     def length
-      @root_timing.children.length
+      children.length
     end
 
-    def profile_node(node, template_name)
+    def profile_node(template_name, code: nil, line_number: nil)
-      start_node(node, template_name)
+      timing = Timing.new(code: code, template_name: template_name, line_number: line_number)
+      parent_children = @current_children
+      start_time = monotonic_time
+      begin
+        @current_children = timing.children
         yield
       ensure
-      end_node
+        @current_children = parent_children
+        timing.total_time = monotonic_time - start_time
+        parent_children << timing
+      end
     end
 
     private
 
-    def start_node(node, template_name)
-      @timing_stack.push(Timing.start(node, template_name))
-    end
-
-    def end_node
-      timing = @timing_stack.pop
-      timing.finish
-
-      @timing_stack.last.children << timing
-    end
-
     def monotonic_time
       Process.clock_gettime(Process::CLOCK_MONOTONIC)
     end

lib/liquid/profiler/hooks.rb

@@ -4,7 +4,7 @@ module Liquid
   module BlockBodyProfilingHook
     def render_node(context, output, node)
       if (profiler = context.profiler)
-        profiler.profile_node(node, context.template_name) do
+        profiler.profile_node(context.template_name, code: node.raw, line_number: node.line_number) do
           super
         end
       else
@@ -17,7 +17,7 @@ module Liquid
   module DocumentProfilingHook
     def render_to_output_buffer(context, output)
       return super unless context.profiler
-      context.profiler.profile { super }
+      context.profiler.profile(context.template_name) { super }
     end
   end
   Document.prepend(DocumentProfilingHook)

test/integration/profiler_test.rb

@@ -103,12 +103,19 @@ class ProfilerTest < Minitest::Test
     with_custom_tag('sleep', SleepTag) do
       context = Liquid::Context.new
       t = Liquid::Template.parse("{% sleep 0.001 %}", profile: true)
+      context.template_name = 'index'
       t.render!(context)
-      first_render_time = context.profiler.total_render_time
+      context.template_name = 'layout'
+      first_render_time = context.profiler.total_time
       t.render!(context)
 
+      profiler = context.profiler
+      children = profiler.children
       assert_operator(first_render_time, :>=, 0.001)
-      assert_operator(context.profiler.total_render_time, :>=, 0.001 + first_render_time)
+      assert_operator(profiler.total_time, :>=, 0.001 + first_render_time)
+      assert_equal(["index", "layout"], children.map(&:template_name))
+      assert_equal([nil, nil], children.map(&:code))
+      assert_equal(profiler.total_time, children.map(&:total_time).reduce(&:+))
     end
   end