liquid/lib/liquid/profiler.rb

module Liquid

  # Profiler enables support for profiling template rendering to help track down performance issues.
  #
  # To enable profiling, pass the <tt>profile: true</tt> option to <tt>Liquid::Template.parse</tt>. Then, after
  # <tt>Liquid::Template#render</tt> is called, the template object makes available an instance of this
  # class via the <tt>Liquid::Template#profiler</tt> method.
  #
  #   template = Liquid::Template.parse(template_content, profile: true)
  #   output  = template.render
  #   profile = template.profiler
  #
  # This object contains all profiling information, containing information on what tags were rendered,
  # where in the templates these tags live, and how long each tag took to render.
  #
  # This is a tree structure that is Enumerable all the way down, and keeps track of tags and rendering times
  # inside of <tt>{% include %}</tt> tags.
  #
  #   profile.each do |node|
  #     # Access to the token itself
  #     node.code
  #
  #     # Which template and line number of this node.
  #     # If top level, this will be "<root>".
  #     node.partial
  #     node.line_number
  #
  #     # Render time in seconds of this node
  #     node.render_time
  #
  #     # If the template used {% include %}, this node will also have children.
  #     node.children.each do |child2|
  #       # ...
  #     end
  #   end
  #
  # Profiler also exposes the total time of the template's render in <tt>Liquid::Profiler#total_render_time</tt>.
  #
  # All render times are in seconds. There is a small performance hit when profiling is enabled.
  #
  class Profiler
    include Enumerable

    class Timing
      attr_reader :code, :partial, :line_number, :children

      def initialize(token, partial)
        @code        = token.respond_to?(:raw) ? token.raw : token
        @partial     = partial
        @line_number = token.respond_to?(:line_number) ? token.line_number : nil
        @children    = []
      end

      def self.start(token, partial)
        new(token, partial).tap do |t|
          t.start
        end
      end

      def start
        @start_time = Time.now
      end

      def finish
        @end_time = Time.now
      end

      def render_time
        @end_time - @start_time
      end
    end

    def self.profile_token_render(token)
      if Profiler.current_profile && token.respond_to?(:render)
        Profiler.current_profile.start_token(token)
        output = yield
        Profiler.current_profile.end_token(token)
        output
      else
        yield
      end
    end

    def self.profile_children(template_name)
      if Profiler.current_profile
        Profiler.current_profile.push_partial(template_name)
        output = yield
        Profiler.current_profile.pop_partial
        output
      else
        yield
      end
    end

    def self.current_profile
      Thread.current[:liquid_profiler]
    end

    def initialize
      @partial_stack = ["<root>"]

      @root_timing = Timing.new("", current_partial)
      @timing_stack = [@root_timing]

      @render_start_at = Time.now
      @render_end_at = @render_start_at
    end

    def start
      Thread.current[:liquid_profiler] = self
      @render_start_at = Time.now
    end

    def stop
      Thread.current[:liquid_profiler] = nil
      @render_end_at = Time.now
    end

    def total_render_time
      @render_end_at - @render_start_at
    end

    def each(&block)
      @root_timing.children.each(&block)
    end

    def [](idx)
      @root_timing.children[idx]
    end

    def length
      @root_timing.children.length
    end

    def start_token(token)
      @timing_stack.push(Timing.start(token, current_partial))
    end

    def end_token(token)
      timing = @timing_stack.pop
      timing.finish

      @timing_stack.last.children << timing
    end

    def current_partial
      @partial_stack.last
    end

    def push_partial(partial_name)
      @partial_stack.push(partial_name)
    end

    def pop_partial
      @partial_stack.pop
    end

  end
end