diff --git a/lib/liquid/document.rb b/lib/liquid/document.rb index 9bf13b4..7742ae5 100644 --- a/lib/liquid/document.rb +++ b/lib/liquid/document.rb @@ -42,7 +42,7 @@ module Liquid end def render(context) - @body.render(context) + render_to_output_buffer(context, +'') end private diff --git a/lib/liquid/profiler.rb b/lib/liquid/profiler.rb index cde2d5b..7a7c376 100644 --- a/lib/liquid/profiler.rb +++ b/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 - @render_start_at = monotonic_time - end - - def stop - @total_render_time = monotonic_time - @render_start_at + def profile + 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 end def each(&block) diff --git a/lib/liquid/profiler/hooks.rb b/lib/liquid/profiler/hooks.rb index b07c580..d005c27 100644 --- a/lib/liquid/profiler/hooks.rb +++ b/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 diff --git a/lib/liquid/template.rb b/lib/liquid/template.rb index 6818ba4..276cdbf 100644 --- a/lib/liquid/template.rb +++ b/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 || +'') - end + @root.render_to_output_buffer(context, output || +'') 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] diff --git a/test/integration/render_profiling_test.rb b/test/integration/render_profiling_test.rb index dc9f001..67ba213 100644 --- a/test/integration/render_profiling_test.rb +++ b/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!