Profiling the rendering of a liquid template

lib/liquid.rb

@@ -70,3 +70,7 @@ module Liquid
 # 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 @@ def parse(tokens)
               # 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 @@ def parse(tokens)
             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 @@ def render_all(list, context)
             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 @@ def render_all(list, context)
 
       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 @@ def initialize(tag_name, markup, options)
     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 @@ def initialize(tag_name, markup, options)
       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 @@ def lookup_class(name)
       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 @@ def register_filter(mod)
       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 @@ def initialize
     # 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 @@ def errors
     # 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 @@ def render(*args)
       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,13 +213,40 @@ def render!(*args)
     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?
 
       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 @@ class Variable
     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 @@ def initialize(markup, options = {})
       end
     end
 
+    def raw
+      @markup
+    end
+
     def lax_parse(markup)
       @filters = []
       if markup =~ /\s*(#{QuotedFragment})(.*)/om