Refactor the profiler into a unified class & measure more things.

lib/jekyll.rb

@@ -63,6 +63,7 @@ module Jekyll
   autoload :Page,                "jekyll/page"
   autoload :PageWithoutAFile,    "jekyll/page_without_a_file"
   autoload :PluginManager,       "jekyll/plugin_manager"
+  autoload :Profiler,            "jekyll/profiler"
   autoload :Publisher,           "jekyll/publisher"
   autoload :Reader,              "jekyll/reader"
   autoload :Regenerator,         "jekyll/regenerator"

lib/jekyll/excerpt.rb

@@ -8,7 +8,7 @@ module Jekyll
     attr_accessor :content, :ext
     attr_writer   :output
 
-    def_delegators :@doc, :site, :name, :ext, :relative_path, :extname,
+    def_delegators :@doc, :site, :name, :ext, :extname,
                           :render_with_liquid?, :collection, :related_posts,
                           :url, :next_doc, :previous_doc
 
@@ -41,6 +41,13 @@ module Jekyll
       File.join(doc.path, "#excerpt")
     end
 
+    # 'Relative path' of the excerpt.
+    #
+    # Returns the path for the doc relative to site source with "#excerpt" appended.
+    def relative_path
+      File.join(doc.relative_path, "#excerpt")
+    end
+
     # Check if excerpt includes a string
     #
     # Returns true if the string passed in

lib/jekyll/liquid_renderer.rb

@@ -1,51 +1,29 @@
 # frozen_string_literal: true
 
 require "jekyll/liquid_renderer/file"
-require "jekyll/liquid_renderer/table"
 
 module Jekyll
   class LiquidRenderer
+    attr_reader :site
+
     def initialize(site)
       @site = site
-      Liquid::Template.error_mode = @site.config["liquid"]["error_mode"].to_sym
-      reset
-    end
-
-    def reset
-      @stats = {}
+      Liquid::Template.error_mode = site.config["liquid"]["error_mode"].to_sym
     end
 
     def file(filename)
       filename = @site.in_source_dir(filename).sub(
-        %r!\A#{Regexp.escape(@site.source)}/!,
+        %r!\A#{Regexp.escape(site.source)}/!,
         ""
       )
 
       LiquidRenderer::File.new(self, filename).tap do
-        @stats[filename] ||= new_profile_hash
-        @stats[filename][:count] += 1
+        site.profiler.increment_count(filename, :liquid)
       end
     end
 
-    def increment_bytes(filename, bytes)
-      @stats[filename][:bytes] += bytes
-    end
-
-    def increment_time(filename, time)
-      @stats[filename][:time] += time
-    end
-
-    def stats_table(n = 50)
-      LiquidRenderer::Table.new(@stats).to_s(n)
-    end
-
     def self.format_error(e, path)
       "#{e.message} in #{path}"
     end
-
-    private
-    def new_profile_hash
-      Hash.new { |hash, key| hash[key] = 0 }
-    end
   end
 end

lib/jekyll/liquid_renderer/file.rb

@@ -40,7 +40,7 @@ module Jekyll
 
       def measure_bytes
         yield.tap do |str|
-          @renderer.increment_bytes(@filename, str.bytesize)
+          @renderer.site.profiler.increment_bytes(@filename, :liquid, str.bytesize)
         end
       end
 
@@ -49,7 +49,7 @@ module Jekyll
         yield
       ensure
         after = Time.now
-        @renderer.increment_time(@filename, after - before)
+        @renderer.site.profiler.increment_time(@filename, :liquid, after - before)
       end
     end
   end

lib/jekyll/liquid_renderer/table.rb

@@ -1,96 +0,0 @@
-# frozen_string_literal: true
-
-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 = String.new("\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 = String.new("")
-
-      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 = String.new("")
-
-      row_data.each_with_index do |cell_data, cell_index|
-        str << if cell_index.zero?
-                 cell_data.ljust(widths[cell_index], " ")
-               else
-                 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 = []
-
-      data.each do |row|
-        row.each_with_index do |cell, index|
-          widths[index] = [ cell.length, widths[index] ].compact.max
-        end
-      end
-
-      widths
-    end
-
-    def data_for_table(n)
-      sorted = @stats.sort_by { |_, file_stats| -file_stats[:time] }
-      sorted = sorted.slice(0, n)
-
-      table = [%w(Filename Count Bytes Time)]
-
-      sorted.each do |filename, file_stats|
-        row = []
-        row << filename
-        row << file_stats[:count].to_s
-        row << format_bytes(file_stats[:bytes])
-        row << format("%.3f", file_stats[:time])
-        table << row
-      end
-
-      table
-    end
-
-    def format_bytes(bytes)
-      bytes /= 1024.0
-      format("%.2fK", bytes)
-    end
-  end
-end

lib/jekyll/profiler.rb

@@ -0,0 +1,88 @@
+# frozen_string_literal: true
+
+require_relative "profiler/table"
+
+module Jekyll
+  class Profiler
+    attr_reader :site, :stats
+
+    def initialize(site)
+      @site = site
+      reset
+    end
+
+    def reset
+      @stats = Hash.new { |hash, filename| hash[filename] = build_profile_hash }
+    end
+
+    def increment_count(filename, context)
+      site.profiler.stats[filename][context][:count] += 1
+    end
+
+    def increment_bytes(filename, context, bytes)
+      site.profiler.stats[filename][context][:bytes] += bytes
+    end
+
+    def increment_time(filename, context, time)
+      site.profiler.stats[filename][context][:time] += time
+    end
+
+    def measure_all(filename, context)
+      increment_count(filename, context)
+      measure_time(filename, context) do
+        measure_bytes(filename, context) do
+          yield
+        end
+      end
+    end
+
+    def measure_bytes(filename, context)
+      yield.tap do |str|
+        increment_bytes(filename, context, str.bytesize)
+      end
+    end
+
+    def measure_time(filename, context)
+      before = Time.now
+      yield
+    ensure
+      after = Time.now
+      increment_time(filename, context, after - before)
+    end
+
+    def stats_table(n = 50)
+      Profiler::Table.new(@stats).to_s(n)
+    end
+
+    def build_profile_hash
+      {
+        :reading => {
+          :bytes => 0,
+          :count => 0,
+          :time  => 0.0,
+        },
+        :rendering => {
+          :bytes => 0,
+          :count => 0,
+          :time  => 0.0,
+        },
+        :markdown => {
+          :bytes => 0,
+          :count => 0,
+          :time  => 0.0,
+        },
+        :liquid => {
+          :bytes => 0,
+          :count => 0,
+          :time  => 0.0,
+        },
+        :writing => {
+          :bytes => 0,
+          :count => 0,
+          :time  => 0.0,
+        },
+      }
+    end
+
+  end
+end

lib/jekyll/profiler/table.rb

@@ -0,0 +1,139 @@
+# frozen_string_literal: true
+
+module Jekyll
+  class Profiler
+    class 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 = String.new("\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 = String.new("")
+
+        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 = String.new("")
+
+        row_data.each_with_index do |cell_data, cell_index|
+          str << if cell_index.zero?
+                   cell_data.ljust(widths[cell_index], " ")
+                 else
+                   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 = []
+
+        data.each do |row|
+          row.each_with_index do |cell, index|
+            widths[index] = [ cell.length, widths[index] ].compact.max
+          end
+        end
+
+        widths
+      end
+
+      def data_for_table(n)
+        sorted = @stats.sort_by { |_, file_stats| -file_stats[:rendering][:time] }
+        sorted = sorted.slice(0, n)
+
+        totals = {
+          :rendering => {
+            :count => 0,
+            :bytes => 0,
+            :time  => 0,
+          },
+          :markdown => {
+            :count => 0,
+            :bytes => 0,
+            :time  => 0,
+          },
+          :liquid => {
+            :bytes => 0,
+            :count => 0,
+            :time  => 0,
+          }
+        }
+
+        # "Markdown Count", "Markdown Bytes", "Markdown Time", "Liquid Count", "Liquid Bytes", "Liquid Time"
+        table = [["Filename", "Count", "Bytes", "Time"]]
+
+        sorted.each do |filename, file_stats|
+          table << build_row(filename, file_stats)
+
+          # :markdown, :liquid
+          [:rendering].each do |context|
+            [:count, :bytes, :time].each do |metric|
+              totals[context][metric] += file_stats[context][metric]
+            end
+          end
+        end
+
+        table << build_row("TOTAL", totals)
+
+        table
+      end
+
+      def build_row(filename, file_stats)
+        # [
+        #   filename,
+        # file_stats[:markdown][:count].to_s,
+        # format_bytes(file_stats[:markdown][:bytes]),
+        # format("%.3f", file_stats[:markdown][:time]),
+        #   file_stats[:liquid][:count].to_s,
+        #   format_bytes(file_stats[:liquid][:bytes]),
+        #   format("%.3f", file_stats[:liquid][:time]),
+        # ]
+        [
+          filename,
+          file_stats[:rendering][:count].to_s,
+          format_bytes(file_stats[:rendering][:bytes]),
+          format("%.3f", file_stats[:rendering][:time]),
+        ]
+      end
+
+      def format_bytes(bytes)
+        bytes /= 1024.0
+        format("%.2fK", bytes)
+      end
+    end
+  end
+end

lib/jekyll/renderer.rb

@@ -49,17 +49,19 @@ module Jekyll
     #
     # Returns String rendered document output
     def run
-      Jekyll.logger.debug "Rendering:", document.relative_path
+      site.profiler.measure_all(document.relative_path, :rendering) do
+        Jekyll.logger.debug "Rendering:", document.relative_path
 
-      assign_pages!
-      assign_related_posts!
-      assign_highlighter_options!
-      assign_layout_data!
+        assign_pages!
+        assign_related_posts!
+        assign_highlighter_options!
+        assign_layout_data!
 
-      Jekyll.logger.debug "Pre-Render Hooks:", document.relative_path
-      document.trigger_hooks(:pre_render, payload)
+        Jekyll.logger.debug "Pre-Render Hooks:", document.relative_path
+        document.trigger_hooks(:pre_render, payload)
 
-      render_document
+        render_document
+      end
     end
 
     # Render the document.
@@ -95,7 +97,7 @@ module Jekyll
     def convert(content)
       converters.reduce(content) do |output, converter|
         begin
-          converter.convert output
+          convert_output_and_profile(output, converter)
         rescue StandardError => e
           Jekyll.logger.error "Conversion error:",
             "#{converter.class} encountered an error while "\
@@ -106,6 +108,17 @@ module Jekyll
       end
     end
 
+    def convert_output_and_profile(output, converter)
+      return converter.convert(output) unless converter.class.name.start_with?("Jekyll::Converters::Markdown")
+
+      site.profiler.increment_count(document.relative_path, :markdown)
+      site.profiler.measure_bytes(document.relative_path, :markdown) do
+        site.profiler.measure_time(document.relative_path, :markdown) do
+          converter.convert(output)
+        end
+      end
+    end
+
     # Render the given content with the payload and info
     #
     # content -

lib/jekyll/site.rb

@@ -12,7 +12,7 @@ module Jekyll
                   :gems, :plugin_manager, :theme
 
     attr_accessor :converters, :generators, :reader
-    attr_reader   :regenerator, :liquid_renderer, :includes_load_paths
+    attr_reader   :regenerator, :liquid_renderer, :includes_load_paths, :profiler
 
     # Public: Initialize a new Site.
     #
@@ -27,6 +27,7 @@ module Jekyll
       @reader          = Reader.new(self)
       @regenerator     = Regenerator.new(self)
       @liquid_renderer = LiquidRenderer.new(self)
+      @profiler        = Profiler.new(self)
 
       Jekyll.sites << self
 
@@ -67,6 +68,7 @@ module Jekyll
     #
     # Returns nothing.
     def process
+      GC.disable
       reset
       read
       generate
@@ -77,7 +79,7 @@ module Jekyll
     end
 
     def print_stats
-      puts @liquid_renderer.stats_table
+      puts profiler.stats_table
     end
 
     # Reset Site details.
@@ -95,7 +97,7 @@ module Jekyll
       self.data = {}
       @collections = nil
       @regenerator.clear_cache
-      @liquid_renderer.reset
+      @profiler.reset
 
       if limit_posts < 0
         raise ArgumentError, "limit_posts must be a non-negative number"
@@ -205,7 +207,10 @@ module Jekyll
     # Returns nothing.
     def write
       each_site_file do |item|
-        item.write(dest) if regenerator.regenerate?(item)
+        next unless regenerator.regenerate?(item)
+        profiler.measure_all(item.relative_path, :writing) do
+          item.write(dest)
+        end
       end
       regenerator.write_metadata
       Jekyll::Hooks.trigger :site, :post_write, self