lib/rodimus/benchmark.rb in rodimus-1.0.0 vs lib/rodimus/benchmark.rb in rodimus-1.1.0

@@ -19,30 +19,45 @@
     end
 
     private
 
     def after_row
-      row_run_time = (Time.now.to_f - @start_time).round(4)
-      stats[:total] = (stats[:total] + row_run_time).round(4)
+      row_run_time = (Time.now.to_f - @row_start_time).round(4)
+      stats[:processing] = (stats[:processing] + row_run_time).round(4)
       stats[:min] = row_run_time if stats[:min] > row_run_time
       stats[:max] = row_run_time if stats[:max] < row_run_time
     end
 
     def before_row
       stats[:count] += 1
-      @start_time = Time.now.to_f
+      @row_start_time = Time.now.to_f
     end
 
     def finalize_stats(subject)
+      stats[:total] = (Time.now.to_f - @start_time).round(4)
       if stats[:count] > 0
-        stats[:average] = (stats[:total] / stats[:count]).round(4)
+        stats[:average] = (stats[:processing] / stats[:count]).round(4)
       end
 
-      Rodimus.logger.info "#{subject} benchmarks: #{stats}"
+      Rodimus.logger.info(subject) { summary }
     end
 
     def initialize_stats
-      @stats = {count: 0, total: 0, min: 1, max: 0, average: 0}
+      @stats = {count: 0, processing: 0, min: 1, max: 0, average: 0}
+      @start_time = Time.now.to_f
+    end
+
+    def summary
+      <<-EOS 
+        \n\t\tTotal time: #{stats[:total]} seconds
+        \tTotal time spent processing: #{stats[:processing]} seconds
+        \tTotal time spent waiting: #{(stats[:total] - stats[:processing]).round(4)} seconds
+        \tTime ratio spent processing: #{(stats[:processing] / stats[:total]).round(4)}
+        \tTotal rows processed: #{stats[:count]}
+        \tFastest row: #{stats[:min]} seconds
+        \tSlowest row: #{stats[:max]} seconds
+        \tAverage row: #{stats[:average]} seconds
+      EOS
     end
   end
 
 end