Merge pull request #364 from collectiveidea/instrument-rendering-with-hooks

Profiling the rendering of a liquid template

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)
+          token_output = render_token(token, context)
-          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
           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 = /(?:\s+|#{QuotedFragment}|#{ArgumentSeparator})+/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