From 173a58d36a32e5c2a968cecb68b45aba932e91c1 Mon Sep 17 00:00:00 2001 From: Jason Roelofs Date: Thu, 5 Jun 2014 14:13:19 -0400 Subject: [PATCH] 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 | 4 + lib/liquid/block.rb | 20 ++- lib/liquid/profiler.rb | 159 ++++++++++++++++++++++ lib/liquid/profiler/hooks.rb | 23 ++++ lib/liquid/profiler/token.rb | 16 +++ lib/liquid/tag.rb | 6 +- lib/liquid/tags/assign.rb | 1 + lib/liquid/template.rb | 41 +++++- lib/liquid/variable.rb | 5 + test/integration/render_profiling_test.rb | 142 +++++++++++++++++++ test/unit/tag_unit_test.rb | 5 + test/unit/tokenizer_unit_test.rb | 9 ++ test/unit/variable_unit_test.rb | 5 + 13 files changed, 427 insertions(+), 9 deletions(-) create mode 100644 lib/liquid/profiler.rb create mode 100644 lib/liquid/profiler/hooks.rb create mode 100644 lib/liquid/profiler/token.rb create mode 100644 test/integration/render_profiling_test.rb diff --git a/lib/liquid.rb b/lib/liquid.rb index dc437d1..c1fac5f 100644 --- a/lib/liquid.rb +++ b/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' diff --git a/lib/liquid/block.rb b/lib/liquid/block.rb index afede69..5503913 100644 --- a/lib/liquid/block.rb +++ b/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 diff --git a/lib/liquid/profiler.rb b/lib/liquid/profiler.rb new file mode 100644 index 0000000..912804d --- /dev/null +++ b/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 profile: true option to Liquid::Template.parse. Then, after + # Liquid::Template#render is called, the template object makes available an instance of this + # class via the Liquid::Template#profiler 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 {% include %} 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 "". + # 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 Liquid::Profiler#total_render_time. + # + # 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_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 diff --git a/lib/liquid/profiler/hooks.rb b/lib/liquid/profiler/hooks.rb new file mode 100644 index 0000000..8a92189 --- /dev/null +++ b/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 diff --git a/lib/liquid/profiler/token.rb b/lib/liquid/profiler/token.rb new file mode 100644 index 0000000..8c43da2 --- /dev/null +++ b/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 + "" + end + + end +end diff --git a/lib/liquid/tag.rb b/lib/liquid/tag.rb index e894e35..b4dfec4 100644 --- a/lib/liquid/tag.rb +++ b/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 diff --git a/lib/liquid/tags/assign.rb b/lib/liquid/tags/assign.rb index 5d82544..cda3878 100644 --- a/lib/liquid/tags/assign.rb +++ b/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 diff --git a/lib/liquid/template.rb b/lib/liquid/template.rb index e2a0c45..d097b05 100644 --- a/lib/liquid/template.rb +++ b/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 Template object from liquid source code + # To enable profiling, pass in profile: true 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 Template.register_filter # + # if profiling was enabled in Template#parse then the resulting profiling information + # will be available via Template#profiler + # # Following options can be passed: # # * filters : 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 diff --git a/lib/liquid/variable.rb b/lib/liquid/variable.rb index 6a35122..fc3a787 100644 --- a/lib/liquid/variable.rb +++ b/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 diff --git a/test/integration/render_profiling_test.rb b/test/integration/render_profiling_test.rb new file mode 100644 index 0000000..fa81d89 --- /dev/null +++ b/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 diff --git a/test/unit/tag_unit_test.rb b/test/unit/tag_unit_test.rb index c5c2a46..4da6ae8 100644 --- a/test/unit/tag_unit_test.rb +++ b/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 diff --git a/test/unit/tokenizer_unit_test.rb b/test/unit/tokenizer_unit_test.rb index e1146d8..f0ae7c9 100644 --- a/test/unit/tokenizer_unit_test.rb +++ b/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) diff --git a/test/unit/variable_unit_test.rb b/test/unit/variable_unit_test.rb index b46aa19..f602f43 100644 --- a/test/unit/variable_unit_test.rb +++ b/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