Fix total_render_time if a Profiler gets used for multiple renders

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
+      started_at = monotonic_time
+      begin
+        @started_at = started_at
+        yield
+      ensure
+        @started_at = nil
+        @total_render_time += monotonic_time - started_at
       end
-
-    def stop
-      @total_render_time = monotonic_time - @render_start_at
     end
 
     def each(&block)

lib/liquid/template.rb

@@ -193,6 +193,10 @@ 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
@@ -221,18 +225,8 @@ module Liquid
     end
 
     def with_profiling(context)
-      if @profiling && context.profiler.nil?
+      return yield unless context.profiler
-        @profiler = context.profiler = Profiler.new
+      context.profiler.profile { yield }
-        @profiler.start
-
-        begin
-          yield
-        ensure
-          @profiler.stop
-        end
-      else
-        yield
-      end
     end
 
     def apply_options_to_context(context, options)

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!