Merge pull request #1365 from Shopify/profiling-multiple-renders

Support using a profiler for multiple renders

lib/liquid/document.rb

@@ -42,7 +42,7 @@ module Liquid
     end
 
     def render(context)
-      @body.render(context)
+      render_to_output_buffer(context, +'')
     end
 
     private

lib/liquid/profiler.rb

@@ -90,14 +90,20 @@ module Liquid
     def initialize
       @root_timing  = Timing.new("", nil)
       @timing_stack = [@root_timing]
+      @render_start_at = nil
+      @total_render_time = 0.0
     end
 
-    def start
+    def profile
-      @render_start_at = monotonic_time
+      return yield if @render_start_at
-    end
+      started_at = monotonic_time
-
+      begin
-    def stop
+        @started_at = started_at
-      @total_render_time = monotonic_time - @render_start_at
+        yield
+      ensure
+        @started_at = nil
+        @total_render_time += monotonic_time - started_at
+      end
     end
 
     def each(&block)

lib/liquid/profiler/hooks.rb

@@ -14,6 +14,14 @@ module Liquid
   end
   BlockBody.prepend(BlockBodyProfilingHook)
 
+  module DocumentProfilingHook
+    def render_to_output_buffer(context, output)
+      return super unless context.profiler
+      context.profiler.profile { super }
+    end
+  end
+  Document.prepend(DocumentProfilingHook)
+
   module ContextProfilingHook
     attr_accessor :profiler
 

lib/liquid/template.rb

@@ -193,11 +193,13 @@ module Liquid
       # Retrying a render resets resource usage
       context.resource_limits.reset
 
+      if @profiling && context.profiler.nil?
+        @profiler = context.profiler = Liquid::Profiler.new
+      end
+
       begin
         # render the nodelist.
-        with_profiling(context) do
+        @root.render_to_output_buffer(context, output || +'')
-          @root.render_to_output_buffer(context, output || +'')
-        end
       rescue Liquid::MemoryError => e
         context.handle_error(e)
       ensure
@@ -220,21 +222,6 @@ module Liquid
       Tokenizer.new(source, @line_numbers)
     end
 
-    def with_profiling(context)
-      if @profiling && context.profiler.nil?
-        @profiler = context.profiler = Profiler.new
-        @profiler.start
-
-        begin
-          yield
-        ensure
-          @profiler.stop
-        end
-      else
-        yield
-      end
-    end
-
     def apply_options_to_context(context, options)
       context.add_filters(options[:filters]) if options[:filters]
       context.global_filter      = options[:global_filter] if options[:global_filter]

test/integration/render_profiling_test.rb

@@ -88,6 +88,30 @@ class RenderProfilingTest < Minitest::Test
     assert(t.profiler.total_render_time >= 0, "Total render time was not calculated")
   end
 
+  class SleepTag < Liquid::Tag
+    def initialize(tag_name, markup, parse_context)
+      super
+      @duration = Float(markup)
+    end
+
+    def render_to_output_buffer(_context, _output)
+      sleep(@duration)
+    end
+  end
+
+  def test_profiling_multiple_renders
+    with_custom_tag('sleep', SleepTag) do
+      context = Liquid::Context.new
+      t = Liquid::Template.parse("{% sleep 0.001 %}", profile: true)
+      t.render!(context)
+      first_render_time = context.profiler.total_render_time
+      t.render!(context)
+
+      assert_operator(first_render_time, :>=, 0.001)
+      assert_operator(context.profiler.total_render_time, :>=, 0.001 + first_render_time)
+    end
+  end
+
   def test_profiling_uses_include_to_mark_children
     t = Template.parse("{{ 'a string' | upcase }}\n{% include 'a_template' %}", profile: true)
     t.render!