Liquid profiler

bin/jekyll

@@ -24,6 +24,7 @@ Mercenary.program(:jekyll) do |p|
   p.option 'safe', '--safe', 'Safe mode (defaults to false)'
   p.option 'plugins', '-p', '--plugins PLUGINS_DIR1[,PLUGINS_DIR2[,...]]', Array, 'Plugins directory (defaults to ./_plugins)'
   p.option 'layouts', '--layouts DIR', String, 'Layouts directory (defaults to ./_layouts)'
+  p.option 'profile', '--profile', 'Generate a Liquid rendering profile'
 
   Jekyll::Command.subclasses.each { |c| c.init_with_program(p) }
 

lib/jekyll.rb

@@ -66,6 +66,7 @@ module Jekyll
   autoload :Regenerator,         'jekyll/regenerator'
   autoload :RelatedPosts,        'jekyll/related_posts'
   autoload :Renderer,            'jekyll/renderer'
+  autoload :LiquidRenderer,      'jekyll/liquid_renderer'
   autoload :Site,                'jekyll/site'
   autoload :StaticFile,          'jekyll/static_file'
   autoload :Stevenson,           'jekyll/stevenson'

lib/jekyll/convertible.rb

@@ -108,8 +108,8 @@ module Jekyll
     # info    - the info for Liquid
     #
     # Returns the converted content
-    def render_liquid(content, payload, info, path = nil)
+    def render_liquid(content, payload, info, path)
-      Liquid::Template.parse(content).render!(payload, info)
+      site.liquid_renderer.file(path).parse(content).render(payload, info)
     rescue Tags::IncludeTagError => e
       Jekyll.logger.error "Liquid Exception:", "#{e.message} in #{e.path}, included in #{path || self.path}"
       raise e
@@ -243,7 +243,7 @@ module Jekyll
       payload["highlighter_prefix"] = converters.first.highlighter_prefix
       payload["highlighter_suffix"] = converters.first.highlighter_suffix
 
-      self.content = render_liquid(content, payload, info) if render_with_liquid?
+      self.content = render_liquid(content, payload, info, path) if render_with_liquid?
       self.content = transform
 
       # output keeps track of what will finally be written

lib/jekyll/liquid_renderer.rb

@@ -0,0 +1,34 @@
+require 'jekyll/liquid_renderer/file'
+require 'jekyll/liquid_renderer/table'
+
+module Jekyll
+  class LiquidRenderer
+    def initialize(site)
+      @site = site
+      reset
+    end
+
+    def reset
+      @stats = {}
+    end
+
+    def file(filename)
+      filename = @site.in_source_dir(filename).sub(/\A#{Regexp.escape(@site.source)}\//, '')
+
+      LiquidRenderer::File.new(self, filename).tap do |file|
+        @stats[filename] ||= {}
+        @stats[filename][:count] ||= 0
+        @stats[filename][:count] += 1
+      end
+    end
+
+    def increment_time(filename, time)
+      @stats[filename][:time] ||= 0.0
+      @stats[filename][:time] += time
+    end
+
+    def stats_table(n = 50)
+      LiquidRenderer::Table.new(@stats).to_s(n)
+    end
+  end
+end

lib/jekyll/liquid_renderer/file.rb

@@ -0,0 +1,40 @@
+module Jekyll
+  class LiquidRenderer
+    class File
+      def initialize(renderer, filename)
+        @renderer = renderer
+        @filename = filename
+      end
+
+      def parse(content)
+        measure_time do
+          @template = Liquid::Template.parse(content)
+        end
+
+        self
+      end
+
+      def render(*args)
+        measure_time do
+          @template.render(*args)
+        end
+      end
+
+      def render!(*args)
+        measure_time do
+          @template.render!(*args)
+        end
+      end
+
+      private
+
+      def measure_time
+        before = Time.now
+        yield
+      ensure
+        after = Time.now
+        @renderer.increment_time(@filename, after - before)
+      end
+    end
+  end
+end

lib/jekyll/liquid_renderer/table.rb

@@ -0,0 +1,88 @@
+module Jekyll
+  class LiquidRenderer::Table
+    def initialize(stats)
+      @stats = stats
+    end
+
+    def to_s(n = 50)
+      data = data_for_table(n)
+      widths = table_widths(data)
+      generate_table(data, widths)
+    end
+
+    private
+
+    def generate_table(data, widths)
+      str = "\n"
+
+      table_head = data.shift
+      str << generate_row(table_head, widths)
+      str << generate_table_head_border(table_head, widths)
+
+      data.each do |row_data|
+        str << generate_row(row_data, widths)
+      end
+
+      str << "\n"
+      str
+    end
+
+    def generate_table_head_border(row_data, widths)
+      str = ""
+
+      row_data.each_index do |cell_index|
+        str << '-' * widths[cell_index]
+        str << '-+-' unless cell_index == row_data.length-1
+      end
+
+      str << "\n"
+      str
+    end
+
+    def generate_row(row_data, widths)
+      str = ''
+
+      row_data.each_with_index do |cell_data, cell_index|
+        if cell_index == 0
+          str << cell_data.ljust(widths[cell_index], ' ')
+        else
+          str << cell_data.rjust(widths[cell_index], ' ')
+        end
+
+        str << ' | ' unless cell_index == row_data.length-1
+      end
+
+      str << "\n"
+      str
+    end
+
+    def table_widths(data)
+      widths = [ 0, 0, 0 ]
+
+      data.each do |row|
+        row.each_with_index do |cell, index|
+          widths[index] = [ cell.length, widths[index] ].max
+        end
+      end
+
+      widths
+    end
+
+    def data_for_table(n)
+      sorted = @stats.sort_by{ |filename, file_stats| -file_stats[:time] }
+      sorted = sorted.slice(0, n)
+
+      table = [[ 'Filename', 'Count', 'Total time' ]]
+
+      sorted.each do |filename, file_stats|
+        row = []
+        row << filename
+        row << file_stats[:count].to_s
+        row << "%.3f" % file_stats[:time]
+        table << row
+      end
+
+      table
+    end
+  end
+end

lib/jekyll/renderer.rb

@@ -49,7 +49,7 @@ module Jekyll
       output = document.content
 
       if document.render_with_liquid?
-        output = render_liquid(output, payload, info)
+        output = render_liquid(output, payload, info, document.path)
       end
 
       output = convert(output)
@@ -92,7 +92,7 @@ module Jekyll
     #
     # Returns the content, rendered by Liquid.
     def render_liquid(content, payload, info, path = nil)
-      Liquid::Template.parse(content).render!(payload, info)
+      site.liquid_renderer.file(path).parse(content).render!(payload, info)
     rescue Tags::IncludeTagError => e
       Jekyll.logger.error "Liquid Exception:", "#{e.message} in #{e.path}, included in #{path || document.relative_path}"
       raise e

lib/jekyll/site.rb

@@ -11,7 +11,7 @@ module Jekyll
                   :gems, :plugin_manager
 
     attr_accessor :converters, :generators, :reader
-    attr_reader   :regenerator
+    attr_reader   :regenerator, :liquid_renderer
 
     # Public: Initialize a new Site.
     #
@@ -33,6 +33,8 @@ module Jekyll
       # Initialize incremental regenerator
       @regenerator = Regenerator.new(self)
 
+      @liquid_renderer = LiquidRenderer.new(self)
+
       self.plugin_manager = Jekyll::PluginManager.new(self)
       self.plugins        = plugin_manager.plugins_path
 
@@ -57,6 +59,13 @@ module Jekyll
       render
       cleanup
       write
+      print_stats
+    end
+
+    def print_stats
+      if @config['profile']
+        puts @liquid_renderer.stats_table
+      end
     end
 
     # Reset Site details.
@@ -70,7 +79,8 @@ module Jekyll
       self.static_files = []
       self.data = {}
       @collections = nil
-      @regenerator.clear_cache()
+      @regenerator.clear_cache
+      @liquid_renderer.reset
 
       if limit_posts < 0
         raise ArgumentError, "limit_posts must be a non-negative number"
@@ -319,7 +329,6 @@ module Jekyll
       end.to_a
     end
 
-
     def each_site_file
       %w(posts pages static_files docs_to_write).each do |type|
         send(type).each do |item|

lib/jekyll/tags/include.rb

@@ -95,7 +95,7 @@ eos
       # Render the variable if required
       def render_variable(context)
         if @file.match(VARIABLE_SYNTAX)
-          partial = Liquid::Template.parse(@file)
+          partial = context.registers[:site].liquid_renderer.file("(variable)").parse(@file)
           partial.render!(context)
         end
       end
@@ -123,7 +123,7 @@ eos
         end
 
         begin
-          partial = Liquid::Template.parse(read_file(path, context))
+          partial = site.liquid_renderer.file(path).parse(read_file(path, context))
 
           context.stack do
             context['include'] = parse_params(context) if @params

test/test_liquid_renderer.rb

@@ -0,0 +1,26 @@
+require 'helper'
+
+class TestLiquidRenderer < JekyllUnitTest
+  context "profiler" do
+    setup do
+      @site = Site.new(site_configuration)
+      @renderer = @site.liquid_renderer
+    end
+
+    should "return a table with profiling results" do
+      @site.process
+
+      output = @renderer.stats_table
+
+      expected = [
+        /^Filename\s+|\s+Count\s+|\s+Total time$/,
+        /^-+\++-+\++-+$/,
+        /^_posts\/2010-01-09-date-override\.markdown\s+|\s+\d+\s+|\s+\d+\.\d{3}$/,
+      ]
+
+      expected.each do |regexp|
+        assert_match regexp, output
+      end
+    end
+  end
+end

test/test_site.rb

@@ -310,7 +310,7 @@ class TestSite < JekyllUnitTest
 
         custom_processor = "CustomMarkdown"
         s = Site.new(site_configuration('markdown' => custom_processor))
-        assert !!s.process
+        s.process
 
         # Do some cleanup, we don't like straggling stuff's.
         Jekyll::Converters::Markdown.send(:remove_const, :CustomMarkdown)
@@ -459,6 +459,17 @@ class TestSite < JekyllUnitTest
       end
     end
 
+    context "with liquid profiling" do
+      setup do
+        @site = Site.new(site_configuration('profile' => true))
+      end
+
+      should "print profile table" do
+        @site.liquid_renderer.should_receive(:stats_table)
+        @site.process
+      end
+    end
+
     context "incremental build" do
       setup do
         @site = Site.new(site_configuration({