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