Profile liquid rendering

Add a simple profiling system to liquid rendering. Each
liquid tag ({{ }} and {% %}) is processed through this profiling,
keeping track of the partial name (in the case of {% include %}), line
number, and the time it took to render the tag. In the case of {%
include %}, the profiler keeps track of the name of the partial and
properly links back tag rendering to the partial and line number for
easy lookup and dive down. With this, it's now possible to track down
exactly how long each tag takes to render.

These hooks get installed and uninstalled on an as-need basis so by
default there is no impact on the overall liquid execution speed.

lib/liquid.rb

@@ -70,3 +70,7 @@ require 'liquid/utils'
 # Load all the tags of the standard library
 #
 Dir[File.dirname(__FILE__) + '/liquid/tags/*.rb'].each { |f| require f }
+
+require 'liquid/profiler'
+require 'liquid/profiler/token'
+require 'liquid/profiler/hooks'

lib/liquid/block.rb

@@ -33,6 +33,7 @@ module Liquid
               # fetch the tag from registered blocks
               if tag = Template.tags[$1]
                 new_tag = tag.parse($1, $2, tokens, @options)
+                new_tag.line_number = token.line_number if token.is_a?(Token)
                 @blank &&= new_tag.blank?
                 @nodelist << new_tag
                 @children << new_tag
@@ -46,6 +47,7 @@ module Liquid
             end
           when token.start_with?(VARSTART)
             new_var = create_variable(token)
+            new_var.line_number = token.line_number if token.is_a?(Token)
             @nodelist << new_var
             @children << new_var
             @blank = false
@@ -134,12 +136,8 @@ module Liquid
             break
           end
 
-          token_output = (token.respond_to?(:render) ? token.render(context) : token)
-          context.increment_used_resources(:render_length_current, token_output)
-          if context.resource_limits_reached?
-            context.resource_limits[:reached] = true
-            raise MemoryError.new("Memory limits exceeded".freeze)
-          end
+          token_output = render_token(token, context)
+
           unless token.is_a?(Block) && token.blank?
             output << token_output
           end
@@ -152,5 +150,15 @@ module Liquid
 
       output.join
     end
+
+    def render_token(token, context)
+      token_output = (token.respond_to?(:render) ? token.render(context) : token)
+      context.increment_used_resources(:render_length_current, token_output)
+      if context.resource_limits_reached?
+        context.resource_limits[:reached] = true
+        raise MemoryError.new("Memory limits exceeded".freeze)
+      end
+      token_output
+    end
   end
 end

lib/liquid/profiler.rb

@@ -0,0 +1,159 @@
+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

lib/liquid/profiler/hooks.rb

@@ -0,0 +1,23 @@
+module Liquid
+  class Block < Tag
+    def render_token_with_profiling(token, context)
+      Profiler.profile_token_render(token) do
+        render_token_without_profiling(token, context)
+      end
+    end
+
+    alias_method :render_token_without_profiling, :render_token
+    alias_method :render_token, :render_token_with_profiling
+  end
+
+  class Include < Tag
+    def render_with_profiling(context)
+      Profiler.profile_children(@template_name) do
+        render_without_profiling(context)
+      end
+    end
+
+    alias_method :render_without_profiling, :render
+    alias_method :render, :render_with_profiling
+  end
+end

lib/liquid/profiler/token.rb

@@ -0,0 +1,16 @@
+module Liquid
+  class Token < String
+
+    attr_reader :line_number
+
+    def initialize(content, line_number)
+      super(content)
+      @line_number = line_number
+    end
+
+    def raw
+      "<raw>"
+    end
+
+  end
+end

lib/liquid/tag.rb

@@ -1,6 +1,6 @@
 module Liquid
   class Tag
-    attr_accessor :options
+    attr_accessor :options, :line_number
     attr_reader :nodelist, :warnings
 
     class << self
@@ -22,6 +22,10 @@ module Liquid
     def parse(tokens)
     end
 
+    def raw
+      "#{@tag_name} #{@markup}"
+    end
+
     def name
       self.class.name.downcase
     end

lib/liquid/tags/assign.rb

@@ -16,6 +16,7 @@ module Liquid
       if markup =~ Syntax
         @to = $1
         @from = Variable.new($2,options)
+        @from.line_number = line_number
       else
         raise SyntaxError.new options[:locale].t("errors.syntax.assign".freeze)
       end

lib/liquid/template.rb

@@ -51,6 +51,8 @@ module Liquid
       end
     end
 
+    attr_reader :profiler
+
     class << self
       # Sets how strict the parser should be.
       # :lax acts like liquid 2.5 and silently ignores malformed tags in most cases.
@@ -85,6 +87,8 @@ module Liquid
       end
 
       # creates a new <tt>Template</tt> object from liquid source code
+      # To enable profiling, pass in <tt>profile: true</tt> as an option.
+      # See Liquid::Profiler for more information
       def parse(source, options = {})
         template = Template.new
         template.parse(source, options)
@@ -99,6 +103,7 @@ module Liquid
     # Parse source code.
     # Returns self for easy chaining
     def parse(source, options = {})
+      @profiling = options.delete(:profile)
       @root = Document.parse(tokenize(source), DEFAULT_OPTIONS.merge(options))
       @warnings = nil
       self
@@ -130,6 +135,9 @@ module Liquid
     # if you use the same filters over and over again consider registering them globally
     # with <tt>Template.register_filter</tt>
     #
+    # if profiling was enabled in <tt>Template#parse</tt> then the resulting profiling information
+    # will be available via <tt>Template#profiler</tt>
+    #
     # Following options can be passed:
     #
     #  * <tt>filters</tt> : array with local filters
@@ -183,7 +191,9 @@ module Liquid
       begin
         # render the nodelist.
         # for performance reasons we get an array back here. join will make a string out of it.
-        result = @root.render(context)
+        result = with_profiling do
+          @root.render(context)
+        end
         result.respond_to?(:join) ? result.join : result
       rescue Liquid::MemoryError => e
         context.handle_error(e)
@@ -203,7 +213,8 @@ module Liquid
     def tokenize(source)
       source = source.source if source.respond_to?(:source)
       return [] if source.to_s.empty?
-      tokens = source.split(TemplateParser)
+
+      tokens = calculate_line_numbers(source.split(TemplateParser))
 
       # removes the rogue empty element at the beginning of the array
       tokens.shift if tokens[0] and tokens[0].empty?
@@ -211,5 +222,31 @@ module Liquid
       tokens
     end
 
+    def calculate_line_numbers(raw_tokens)
+      return raw_tokens unless @profiling
+
+      current_line = 1
+      raw_tokens.map do |token|
+        Token.new(token, current_line).tap do
+          current_line += token.count("\n")
+        end
+      end
+    end
+
+    def with_profiling
+      if @profiling
+        @profiler = Profiler.new
+        @profiler.start
+
+        begin
+          yield
+        ensure
+          @profiler.stop
+        end
+      else
+        yield
+      end
+    end
+
   end
 end

lib/liquid/variable.rb

@@ -14,6 +14,7 @@ module Liquid
     FilterParser = /(?:#{FilterSeparator}|(?:\s*(?:#{QuotedFragment}|#{ArgumentSeparator})\s*)+)/o
     EasyParse = /\A *(\w+(?:\.\w+)*) *\z/
     attr_accessor :filters, :name, :warnings
+    attr_accessor :line_number
 
     def initialize(markup, options = {})
       @markup  = markup
@@ -34,6 +35,10 @@ module Liquid
       end
     end
 
+    def raw
+      @markup
+    end
+
     def lax_parse(markup)
       @filters = []
       if markup =~ /\s*(#{QuotedFragment})(.*)/om

test/integration/render_profiling_test.rb

@@ -0,0 +1,142 @@
+require 'test_helper'
+
+class RenderProfilingTest < Minitest::Test
+  include Liquid
+
+  class ProfilingFileSystem
+    def read_template_file(template_path, context)
+      "Rendering template {% assign template_name = '#{template_path}'%}\n{{ template_name }}"
+    end
+  end
+
+  def setup
+    Liquid::Template.file_system = ProfilingFileSystem.new
+  end
+
+  def test_template_allows_flagging_profiling
+    t = Template.parse("{{ 'a string' | upcase }}")
+    t.render!
+
+    assert_nil t.profiler
+  end
+
+  def test_parse_makes_available_simple_profiling
+    t = Template.parse("{{ 'a string' | upcase }}", :profile => true)
+    t.render!
+
+    assert_equal 1, t.profiler.length
+
+    node = t.profiler[0]
+    assert_equal " 'a string' | upcase ", node.code
+  end
+
+  def test_render_ignores_raw_strings_when_profiling
+    t = Template.parse("This is raw string\nstuff\nNewline", :profile => true)
+    t.render!
+
+    assert_equal 0, t.profiler.length
+  end
+
+  def test_profiling_includes_line_numbers_of_liquid_nodes
+    t = Template.parse("{{ 'a string' | upcase }}\n{% increment test %}", :profile => true)
+    t.render!
+    assert_equal 2, t.profiler.length
+
+    # {{ 'a string' | upcase }}
+    assert_equal 1, t.profiler[0].line_number
+    # {{ increment test }}
+    assert_equal 2, t.profiler[1].line_number
+  end
+
+  def test_profiling_times_the_rendering_of_tokens
+    t = Template.parse("{% include 'a_template' %}", :profile => true)
+    t.render!
+
+    node = t.profiler[0]
+    refute_nil node.render_time
+  end
+
+  def test_profiling_times_the_entire_render
+    t = Template.parse("{% include 'a_template' %}", :profile => true)
+    t.render!
+
+    assert t.profiler.total_render_time > 0, "Total render time was not calculated"
+  end
+
+  def test_profiling_uses_include_to_mark_children
+    t = Template.parse("{{ 'a string' | upcase }}\n{% include 'a_template' %}", :profile => true)
+    t.render!
+
+    include_node = t.profiler[1]
+    assert_equal 2, include_node.children.length
+  end
+
+  def test_profiling_marks_children_with_the_name_of_included_partial
+    t = Template.parse("{{ 'a string' | upcase }}\n{% include 'a_template' %}", :profile => true)
+    t.render!
+
+    include_node = t.profiler[1]
+    include_node.children.each do |child|
+      assert_equal "'a_template'", child.partial
+    end
+  end
+
+  def test_profiling_supports_multiple_templates
+    t = Template.parse("{{ 'a string' | upcase }}\n{% include 'a_template' %}\n{% include 'b_template' %}", :profile => true)
+    t.render!
+
+    a_template = t.profiler[1]
+    a_template.children.each do |child|
+      assert_equal "'a_template'", child.partial
+    end
+
+    b_template = t.profiler[2]
+    b_template.children.each do |child|
+      assert_equal "'b_template'", child.partial
+    end
+  end
+
+  def test_profiling_supports_rendering_the_same_partial_multiple_times
+    t = Template.parse("{{ 'a string' | upcase }}\n{% include 'a_template' %}\n{% include 'a_template' %}", :profile => true)
+    t.render!
+
+    a_template1 = t.profiler[1]
+    a_template1.children.each do |child|
+      assert_equal "'a_template'", child.partial
+    end
+
+    a_template2 = t.profiler[2]
+    a_template2.children.each do |child|
+      assert_equal "'a_template'", child.partial
+    end
+  end
+
+  def test_can_iterate_over_each_profiling_entry
+    t = Template.parse("{{ 'a string' | upcase }}\n{% increment test %}", :profile => true)
+    t.render!
+
+    timing_count = 0
+    t.profiler.each do |timing|
+      timing_count += 1
+    end
+
+    assert_equal 2, timing_count
+  end
+
+  def test_profiling_marks_children_of_if_blocks
+    t = Template.parse("{% if true %} {% increment test %} {{ test }} {% endif %}", :profile => true)
+    t.render!
+
+    assert_equal 1, t.profiler.length
+    assert_equal 2, t.profiler[0].children.length
+  end
+
+  def test_profiling_marks_children_of_for_blocks
+    t = Template.parse("{% for item in collection %} {{ item }} {% endfor %}", :profile => true)
+    t.render!({"collection" => ["one", "two"]})
+
+    assert_equal 1, t.profiler.length
+    # Will profile each invocation of the for block
+    assert_equal 2, t.profiler[0].children.length
+  end
+end

test/unit/tag_unit_test.rb

@@ -8,4 +8,9 @@ class TagUnitTest < Minitest::Test
     assert_equal 'liquid::tag', tag.name
     assert_equal '', tag.render(Context.new)
   end
+
+  def test_return_raw_text_of_tag
+    tag = Tag.parse("long_tag", "param1, param2, param3", [], {})
+    assert_equal("long_tag param1, param2, param3", tag.raw)
+  end
 end

test/unit/tokenizer_unit_test.rb

@@ -21,6 +21,15 @@ class TokenizerTest < Minitest::Test
     assert_equal ['  ', '{% comment %}', ' ', '{% endcomment %}', ' '], tokenize("  {% comment %} {% endcomment %} ")
   end
 
+  def test_calculate_line_numbers_per_token_with_profiling
+    template = Liquid::Template.parse("", :profile => true)
+
+    assert_equal [1],       template.send(:tokenize, "{{funk}}").map(&:line_number)
+    assert_equal [1, 1, 1], template.send(:tokenize, " {{funk}} ").map(&:line_number)
+    assert_equal [1, 2, 2], template.send(:tokenize, "\n{{funk}}\n").map(&:line_number)
+    assert_equal [1, 1, 3], template.send(:tokenize, " {{\n funk \n}} ").map(&:line_number)
+  end
+
   private
 
   def tokenize(source)

test/unit/variable_unit_test.rb

@@ -133,4 +133,9 @@ class VariableUnitTest < Minitest::Test
       end
     end
   end
+
+  def test_output_raw_source_of_variable
+    var = Variable.new(%! name_of_variable | upcase !)
+    assert_equal " name_of_variable | upcase ", var.raw
+  end
 end