diff --git a/lib/liquid/profiler.rb b/lib/liquid/profiler.rb index 7a7c3764..f88f520a 100644 --- a/lib/liquid/profiler.rb +++ b/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) - @code = node.respond_to?(:raw) ? node.raw : node - @partial = template_name - @line_number = node.respond_to?(:line_number) ? node.line_number : nil - @children = [] + def initialize(code: nil, template_name: nil, line_number: nil) + @code = code + @template_name = template_name + @line_number = line_number + @children = [] end - def self.start(node, template_name) - new(node, template_name).tap(&:start) - end - - 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 + def self_time + @self_time ||= begin + total_children_time = 0.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) + def initialize + @root_children = [] + @current_children = nil + @total_time = 0.0 + end + + def profile(template_name, &block) + # nested renders are done from a tag that already has a timing node + return yield if @current_children + + root_children = @root_children + render_idx = root_children.length + begin + @current_children = root_children + profile_node(template_name, &block) + ensure + @current_children = nil + if (timing = root_children[render_idx]) + @total_time += timing.total_time + end end end - attr_reader :total_render_time - - def initialize - @root_timing = Timing.new("", nil) - @timing_stack = [@root_timing] - @render_start_at = nil - @total_render_time = 0.0 - end - - 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 + 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) - start_node(node, template_name) - yield - ensure - end_node + def profile_node(template_name, code: nil, line_number: nil) + 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 + @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 diff --git a/lib/liquid/profiler/hooks.rb b/lib/liquid/profiler/hooks.rb index d005c279..0c3ac14d 100644 --- a/lib/liquid/profiler/hooks.rb +++ b/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) diff --git a/test/integration/profiler_test.rb b/test/integration/profiler_test.rb index 0de84d03..0d7fee32 100644 --- a/test/integration/profiler_test.rb +++ b/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