From 8a48c8174e10b1f307d5d2eb28fb15fba5de4f35 Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 9 Feb 2018 15:56:38 +0530 Subject: [PATCH 1/8] profile site process --- lib/jekyll/liquid_renderer.rb | 34 ++++++++++++++++++++++++++++++++++ lib/jekyll/site.rb | 34 +++++++++++++++++++++++++++------- 2 files changed, 61 insertions(+), 7 deletions(-) diff --git a/lib/jekyll/liquid_renderer.rb b/lib/jekyll/liquid_renderer.rb index 3c731724657..c76d1cec276 100644 --- a/lib/jekyll/liquid_renderer.rb +++ b/lib/jekyll/liquid_renderer.rb @@ -39,6 +39,27 @@ def stats_table(n = 50) LiquidRenderer::Table.new(@stats).to_s(n) end + # rubocop:disable Metrics/AbcSize + def print(data) + cell_width = data.keys.map(&:length).max + cell_border = "-" * (cell_width + 2) + total_time = data.delete("TOTAL TIME") + + String.new("\nBuild Process Summary:\n").tap do |table| + table << "-" * 22 << "\n\n" + table << format_data_cell("METHOD", "TIME", cell_width) + table << divider(cell_border) + + data.each do |key, value| + table << format_data_cell(key, format("%.4f", value), cell_width) + end + + table << divider(cell_border) + table << format_data_cell("TOTAL TIME", format("%.4f", total_time), cell_width) + end + end + # rubocop:enable Metrics/AbcSize + def self.format_error(e, path) "#{e.message} in #{path}" end @@ -47,5 +68,18 @@ def self.format_error(e, path) def new_profile_hash Hash.new { |hash, key| hash[key] = 0 } end + + private + def format_data_cell(key, val, width) + String.new("").tap do |row| + row << key.to_s.ljust(width - 2).center(width + 2) << " | " + row << val.to_s.rjust(width - 4).center(width + 2) << "\n" + end + end + + private + def divider(cell_border) + String.new("") << cell_border << "-+-" << cell_border << "\n" + end end end diff --git a/lib/jekyll/site.rb b/lib/jekyll/site.rb index fafa3dd6557..8d04ca725a7 100644 --- a/lib/jekyll/site.rb +++ b/lib/jekyll/site.rb @@ -67,13 +67,8 @@ def config=(config) # # Returns nothing. def process - reset - read - generate - render - cleanup - write - print_stats if config["profile"] + return profile_process if config["profile"] + process_methods.each { |method| public_send(method) } end def print_stats @@ -476,5 +471,30 @@ def render_regenerated(document, payload) document.output = Jekyll::Renderer.new(self, document, payload).run document.trigger_hooks(:post_render) end + + private + def process_methods + %w(reset read generate render cleanup write) + end + + private + def profile_process + profile_data = {} + total_time = 0 + + process_methods.each do |method| + start_time = Time.now + public_send(method) + end_time = (Time.now - start_time).round(4) + profile_data[method.upcase] = end_time + total_time += end_time + end + + profile_data["TOTAL TIME"] = total_time + + Jekyll.logger.info @liquid_renderer.print(profile_data).cyan + Jekyll.logger.info "\nSite Render Stats:\n------------------" + print_stats + end end end From 808b4f1d245449fe1f9417386457d6385cadd00c Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 9 Feb 2018 16:13:23 +0530 Subject: [PATCH 2/8] run default-site script with --profile option --- script/default-site | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/script/default-site b/script/default-site index 899524a710d..0504fd3815e 100755 --- a/script/default-site +++ b/script/default-site @@ -16,5 +16,5 @@ ruby -e "contents = File.read('Gemfile'); File.write('Gemfile', contents.sub(/ge echo "$0: installing default site dependencies" BUNDLE_GEMFILE=Gemfile bundle install echo "$0: building the default site" -BUNDLE_GEMFILE=Gemfile bundle exec jekyll build --verbose +BUNDLE_GEMFILE=Gemfile bundle exec jekyll build --verbose --profile popd From ad5f8977bfde69cafd0de1c2bee6c5a0bcf31bb3 Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 9 Feb 2018 17:08:28 +0530 Subject: [PATCH 3/8] un-DRY a bit --- lib/jekyll/site.rb | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/lib/jekyll/site.rb b/lib/jekyll/site.rb index 8d04ca725a7..e05a401002e 100644 --- a/lib/jekyll/site.rb +++ b/lib/jekyll/site.rb @@ -68,7 +68,12 @@ def config=(config) # Returns nothing. def process return profile_process if config["profile"] - process_methods.each { |method| public_send(method) } + reset + read + generate + render + cleanup + write end def print_stats From 012ed259523121837208669c564fa1aaf2bc4c0a Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 9 Feb 2018 17:20:37 +0530 Subject: [PATCH 4/8] absorb unnecessary private method --- lib/jekyll/site.rb | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/lib/jekyll/site.rb b/lib/jekyll/site.rb index e05a401002e..eff5df2a937 100644 --- a/lib/jekyll/site.rb +++ b/lib/jekyll/site.rb @@ -477,17 +477,12 @@ def render_regenerated(document, payload) document.trigger_hooks(:post_render) end - private - def process_methods - %w(reset read generate render cleanup write) - end - private def profile_process profile_data = {} total_time = 0 - process_methods.each do |method| + %w(reset read generate render cleanup write).each do |method| start_time = Time.now public_send(method) end_time = (Time.now - start_time).round(4) From 53d2d3ba14a918025b9677f8715888ab6e3d7caf Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Wed, 25 Jul 2018 15:59:43 +0530 Subject: [PATCH 5/8] initialize Jekyll::Profiler to profile all stages --- lib/jekyll.rb | 1 + lib/jekyll/liquid_renderer.rb | 30 ------------------ lib/jekyll/profiler.rb | 60 +++++++++++++++++++++++++++++++++++ lib/jekyll/site.rb | 24 ++------------ 4 files changed, 64 insertions(+), 51 deletions(-) create mode 100644 lib/jekyll/profiler.rb diff --git a/lib/jekyll.rb b/lib/jekyll.rb index 56a9b84f5b2..945e70a66ef 100644 --- a/lib/jekyll.rb +++ b/lib/jekyll.rb @@ -66,6 +66,7 @@ module Jekyll autoload :PageWithoutAFile, "jekyll/page_without_a_file" autoload :PluginManager, "jekyll/plugin_manager" autoload :Publisher, "jekyll/publisher" + autoload :Profiler, "jekyll/profiler" autoload :Reader, "jekyll/reader" autoload :Regenerator, "jekyll/regenerator" autoload :RelatedPosts, "jekyll/related_posts" diff --git a/lib/jekyll/liquid_renderer.rb b/lib/jekyll/liquid_renderer.rb index bb4c7de564e..4e76fc82653 100644 --- a/lib/jekyll/liquid_renderer.rb +++ b/lib/jekyll/liquid_renderer.rb @@ -46,26 +46,6 @@ def stats_table(num_of_rows = 50) LiquidRenderer::Table.new(@stats).to_s(num_of_rows) end - # rubocop:disable Metrics/AbcSize - def print(data) - cell_width = data.keys.map(&:length).max - cell_border = "-" * (cell_width + 2) - total_time = data.delete("TOTAL TIME") - - table = +"\nBuild Process Summary:\n" - table << "-" * 22 << "\n\n" - table << format_data_cell("METHOD", "TIME", cell_width) - table << divider(cell_border) - - data.each do |key, value| - table << format_data_cell(key, format("%.4f", value), cell_width) - end - - table << divider(cell_border) - table << format_data_cell("TOTAL TIME", format("%.4f", total_time), cell_width) - end - # rubocop:enable Metrics/AbcSize - def self.format_error(error, path) "#{error.message} in #{path}" end @@ -79,15 +59,5 @@ def filename_regex def new_profile_hash Hash.new { |hash, key| hash[key] = 0 } end - - def format_data_cell(key, val, width) - row = +"" - row << key.to_s.ljust(width - 2).center(width + 2) << " | " - row << val.to_s.rjust(width - 4).center(width + 2) << "\n" - end - - def divider(cell_border) - +"" << cell_border << "-+-" << cell_border << "\n" - end end end diff --git a/lib/jekyll/profiler.rb b/lib/jekyll/profiler.rb new file mode 100644 index 00000000000..593cf76a098 --- /dev/null +++ b/lib/jekyll/profiler.rb @@ -0,0 +1,60 @@ +# frozen_string_literal: true + +module Jekyll + class Profiler + def initialize(site) + @site = site + end + + def profile_process + profile_data = {} + total_time = 0 + + [:reset, :read, :generate, :render, :cleanup, :write].each do |method| + start_time = Time.now + @site.send(method) + end_time = (Time.now - start_time).round(4) + profile_data[method.to_s.upcase] = end_time + total_time += end_time + end + + profile_data["TOTAL TIME"] = total_time + Jekyll.logger.info print_phase_stats(profile_data) + + Jekyll.logger.info "\nSite Render Stats:\n------------------" + @site.print_stats + end + + private + + # rubocop:disable Metrics/AbcSize + def print_phase_stats(data) + cell_width = data.keys.map(&:length).max + cell_border = "-" * (cell_width + 2) + total_time = data.delete("TOTAL TIME") + + table = +"\nBuild Process Summary:\n" + table << "-" * 22 << "\n\n" + table << format_data_cell("PHASE", "TIME", cell_width) + table << divider(cell_border) + + data.each do |key, value| + table << format_data_cell(key, format("%.4f", value), cell_width) + end + + table << divider(cell_border) + table << format_data_cell("TOTAL TIME", format("%.4f", total_time), cell_width) + end + # rubocop:enable Metrics/AbcSize + + def format_data_cell(key, val, width) + row = +"" + row << key.to_s.ljust(width - 2).center(width + 2) << " | " + row << val.to_s.rjust(width) << "\n" + end + + def divider(cell_border) + +"" << cell_border << "-+-" << cell_border << "\n" + end + end +end diff --git a/lib/jekyll/site.rb b/lib/jekyll/site.rb index 5b0094e8385..dff2dea2c06 100644 --- a/lib/jekyll/site.rb +++ b/lib/jekyll/site.rb @@ -10,7 +10,7 @@ class Site :gems, :plugin_manager, :theme attr_accessor :converters, :generators, :reader - attr_reader :regenerator, :liquid_renderer, :includes_load_paths + attr_reader :regenerator, :liquid_renderer, :profiler, :includes_load_paths # Public: Initialize a new Site. # @@ -23,6 +23,7 @@ def initialize(config) self.config = config @reader = Reader.new(self) + @profiler = Profiler.new(self) @regenerator = Regenerator.new(self) @liquid_renderer = LiquidRenderer.new(self) @@ -65,7 +66,7 @@ def config=(config) # # Returns nothing. def process - return profile_process if config["profile"] + return profiler.profile_process if config["profile"] reset read generate @@ -470,24 +471,5 @@ def render_regenerated(document, payload) document.output = Jekyll::Renderer.new(self, document, payload).run document.trigger_hooks(:post_render) end - - def profile_process - profile_data = {} - total_time = 0 - - %w(reset read generate render cleanup write).each do |method| - start_time = Time.now - public_send(method) - end_time = (Time.now - start_time).round(4) - profile_data[method.upcase] = end_time - total_time += end_time - end - - profile_data["TOTAL TIME"] = total_time - - Jekyll.logger.info @liquid_renderer.print(profile_data).cyan - Jekyll.logger.info "\nSite Render Stats:\n------------------" - print_stats - end end end From 3bcf8428a2895c170d40f48a8b0cafb9b6fd0986 Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 17 Jan 2020 16:54:05 +0530 Subject: [PATCH 6/8] Revert change to liquid_renderer --- lib/jekyll/liquid_renderer.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/jekyll/liquid_renderer.rb b/lib/jekyll/liquid_renderer.rb index 4e76fc82653..55e4e0fb014 100644 --- a/lib/jekyll/liquid_renderer.rb +++ b/lib/jekyll/liquid_renderer.rb @@ -53,7 +53,7 @@ def self.format_error(error, path) private def filename_regex - @filename_regex ||= %r!\A(#{source_dir}/|#{theme_dir}/|/*)(.*)!i + @filename_regex ||= %r!\A(#{source_dir}/|#{theme_dir}/|\W*)(.*)!i end def new_profile_hash From b6f077f5175468f1a07b991a1469e975d553bc0a Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 17 Jan 2020 21:21:36 +0530 Subject: [PATCH 7/8] Integrate Profiler into LiquidRenderer::Table --- lib/jekyll/liquid_renderer/table.rb | 22 +-------- lib/jekyll/profiler.rb | 72 ++++++++++++++--------------- 2 files changed, 36 insertions(+), 58 deletions(-) diff --git a/lib/jekyll/liquid_renderer/table.rb b/lib/jekyll/liquid_renderer/table.rb index a55bb8c9201..b354b15d379 100644 --- a/lib/jekyll/liquid_renderer/table.rb +++ b/lib/jekyll/liquid_renderer/table.rb @@ -10,31 +10,11 @@ def initialize(stats) end def to_s(num_of_rows = 50) - tabulate(data_for_table(num_of_rows)) + Jekyll::Profiler.tabulate(data_for_table(num_of_rows)) end private - def tabulate(data) - require "terminal-table" - - header = data.shift - footer = data.pop - output = +"\n" - - table = Terminal::Table.new do |t| - t << header - t << :separator - data.each { |row| t << row } - t << :separator - t << footer - t.style = { :alignment => :right, :border_top => false, :border_bottom => false } - t.align_column(0, :left) - end - - output << table.to_s << "\n" - end - # rubocop:disable Metrics/AbcSize def data_for_table(num_of_rows) sorted = @stats.sort_by { |_, file_stats| -file_stats[:time] } diff --git a/lib/jekyll/profiler.rb b/lib/jekyll/profiler.rb index 593cf76a098..aef74c26aab 100644 --- a/lib/jekyll/profiler.rb +++ b/lib/jekyll/profiler.rb @@ -2,59 +2,57 @@ module Jekyll class Profiler + TERMINAL_TABLE_STYLES = { + :alignment => :right, + :border_top => false, + :border_bottom => false, + }.freeze + private_constant :TERMINAL_TABLE_STYLES + + def self.tabulate(table_rows) + require "terminal-table" + + rows = table_rows.dup + header = rows.shift + footer = rows.pop + output = +"\n" + + table = Terminal::Table.new do |t| + t << header + t << :separator + rows.each { |row| t << row } + t << :separator + t << footer + t.style = TERMINAL_TABLE_STYLES + t.align_column(0, :left) + end + + output << table.to_s << "\n" + end + def initialize(site) @site = site end def profile_process - profile_data = {} + profile_data = { "PHASE" => "TIME" } total_time = 0 [:reset, :read, :generate, :render, :cleanup, :write].each do |method| start_time = Time.now @site.send(method) end_time = (Time.now - start_time).round(4) - profile_data[method.to_s.upcase] = end_time + profile_data[method.to_s.upcase.cyan] = format("%.4f", end_time) total_time += end_time end - profile_data["TOTAL TIME"] = total_time - Jekyll.logger.info print_phase_stats(profile_data) - - Jekyll.logger.info "\nSite Render Stats:\n------------------" - @site.print_stats - end - - private - - # rubocop:disable Metrics/AbcSize - def print_phase_stats(data) - cell_width = data.keys.map(&:length).max - cell_border = "-" * (cell_width + 2) - total_time = data.delete("TOTAL TIME") - - table = +"\nBuild Process Summary:\n" - table << "-" * 22 << "\n\n" - table << format_data_cell("PHASE", "TIME", cell_width) - table << divider(cell_border) - - data.each do |key, value| - table << format_data_cell(key, format("%.4f", value), cell_width) - end - - table << divider(cell_border) - table << format_data_cell("TOTAL TIME", format("%.4f", total_time), cell_width) - end - # rubocop:enable Metrics/AbcSize + profile_data["TOTAL TIME"] = format("%.4f", total_time) - def format_data_cell(key, val, width) - row = +"" - row << key.to_s.ljust(width - 2).center(width + 2) << " | " - row << val.to_s.rjust(width) << "\n" - end + Jekyll.logger.info "\nBuild Process Summary:".cyan + Jekyll.logger.info Profiler.tabulate(Array(profile_data)) - def divider(cell_border) - +"" << cell_border << "-+-" << cell_border << "\n" + Jekyll.logger.info "\nSite Render Stats:".cyan + @site.print_stats end end end From 7adf70b03edf8c92951c7f12883a13f436914b5d Mon Sep 17 00:00:00 2001 From: Ashwin Maroli Date: Fri, 17 Jan 2020 21:41:49 +0530 Subject: [PATCH 8/8] Do not colorize strings --- lib/jekyll/profiler.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/jekyll/profiler.rb b/lib/jekyll/profiler.rb index aef74c26aab..0025912cf00 100644 --- a/lib/jekyll/profiler.rb +++ b/lib/jekyll/profiler.rb @@ -42,16 +42,16 @@ def profile_process start_time = Time.now @site.send(method) end_time = (Time.now - start_time).round(4) - profile_data[method.to_s.upcase.cyan] = format("%.4f", end_time) + profile_data[method.to_s.upcase] = format("%.4f", end_time) total_time += end_time end profile_data["TOTAL TIME"] = format("%.4f", total_time) - Jekyll.logger.info "\nBuild Process Summary:".cyan + Jekyll.logger.info "\nBuild Process Summary:" Jekyll.logger.info Profiler.tabulate(Array(profile_data)) - Jekyll.logger.info "\nSite Render Stats:".cyan + Jekyll.logger.info "\nSite Render Stats:" @site.print_stats end end