Merge pull request #365 from nanoc/bug/broken-verbose-compile-output

Fix profiling feedback formatting

lib/nanoc/cli/commands/compile.rb

@@ -162,33 +162,33 @@ def self.enable_for?(command_runner)
 
       # @option params [Array<Nanoc::ItemRep>] :reps The list of item representations in the site
       def initialize(params={})
-        @filter_times = {}
+        @times = {}
 
-        @reps       = params.fetch(:reps)
+        @reps = params.fetch(:reps)
       end
 
       # @see Listener#start
       def start
         Nanoc::NotificationCenter.on(:filtering_started) do |rep, filter_name|
-          @filter_times[filter_name] ||= []
-          @filter_times[filter_name] << Time.now
+          @times[filter_name] ||= []
+          @times[filter_name] << { :start => Time.now }
         end
         Nanoc::NotificationCenter.on(:filtering_ended) do |rep, filter_name|
-          @filter_times[filter_name] << Time.now - @filter_times[filter_name].pop
+          @times[filter_name].last[:stop] = Time.now
         end
       end
 
       # @see Listener#stop
       def stop
-        super
         self.print_profiling_feedback
+        super
       end
 
     protected
 
       def print_profiling_feedback
         # Get max filter length
-        max_filter_name_length = @filter_times.keys.map { |k| k.to_s.size }.max
+        max_filter_name_length = durations_per_filter.keys.map { |k| k.to_s.size }.max
         return if max_filter_name_length.nil?
 
         # Print warning if necessary
@@ -203,19 +203,19 @@ def print_profiling_feedback
         puts ' ' * max_filter_name_length + ' | count    min    avg    max     tot'
         puts '-' * max_filter_name_length + '-+-----------------------------------'
 
-        @filter_times.to_a.sort_by { |r| r[1] }.each do |row|
-          self.print_row(row)
+        durations_per_filter.to_a.sort_by { |r| r[1] }.each do |row|
+          self.print_row(row, max_filter_name_length)
         end
       end
 
-      def print_row(row)
+      def print_row(row, length)
         # Extract data
         filter_name, samples = *row
 
         # Calculate stats
         count = samples.size
         min   = samples.min
-        tot   = samples.inject { |memo, i| memo + i}
+        tot   = samples.inject(0) { |memo, i| memo + i }
         avg   = tot/count
         max   = samples.max
 
@@ -227,8 +227,26 @@ def print_row(row)
         tot   = format('%5.2f', tot)
 
         # Output stats
-        filter_name = format("%#{max}s", filter_name)
-        puts "#{filter_name} |  #{count}  #{min}s  #{avg}s  #{max}s  #{tot}s"
+        key = format("%#{length}s", filter_name)
+        puts "#{key} |  #{count}  #{min}s  #{avg}s  #{max}s  #{tot}s"
+      end
+
+      def durations_per_filter
+        @_durations_per_filter ||= begin
+          @times.keys.each_with_object({}) do |filter_name, result|
+            if durations = durations_for_filter(filter_name)
+              result[filter_name] = durations
+            end
+          end
+        end
+      end
+
+      def durations_for_filter(filter_name)
+        @times[filter_name].each_with_object([]) do |sample, result|
+          if sample[:start] && sample[:stop]
+            result << sample[:stop] - sample[:start]
+          end
+        end
       end
 
     end
@@ -310,7 +328,7 @@ def start
     # Prints file actions (created, updated, deleted, identical, skipped)
     class FileActionPrinter < Listener
 
-      # @option params [Array<Nanoc::ItemRep>] :reps The list of item representations in the site 
+      # @option params [Array<Nanoc::ItemRep>] :reps The list of item representations in the site
       def initialize(params={})
         @rep_times       = {}
 
@@ -371,7 +389,7 @@ def run
 
   protected
 
-    def prune  
+    def prune
       if self.site.config[:prune][:auto_prune]
         Nanoc::Extra::Pruner.new(self.site, :exclude => self.prune_config_exclude).run
       end