Merge pull request nanoc#1287 from nanoc/upgrade-ddmetrics-and-ddmemoize

Upgrade DDMetrics and DDMemoize

Author: denisdefreyne

nanoc/lib/nanoc.rb

@@ -7,9 +7,9 @@
 require 'ref'
 require 'slow_enumerator_tools'
 require 'ddmemoize'
-require 'ddtelemetry'
+require 'ddmetrics'
 
-DDMemoize.enable_telemetry
+DDMemoize.enable_metrics
 
 module Nanoc
   # @return [String] A string containing information about this Nanoc version

nanoc/lib/nanoc/base/services/instrumentor.rb

@@ -4,7 +4,7 @@ module Nanoc::Int
   # @api private
   class Instrumentor
     def self.call(key, *args)
-      stopwatch = DDTelemetry::Stopwatch.new
+      stopwatch = DDMetrics::Stopwatch.new
       stopwatch.start
       yield
     ensure

nanoc/lib/nanoc/cli/commands/compile_listeners/timing_recorder.rb

@@ -16,40 +16,40 @@ def self.enable_for?(_command_runner, _site)
     def initialize(reps:)
       @reps = reps
 
-      @stages_summary = DDTelemetry::Summary.new
-      @phases_summary = DDTelemetry::Summary.new
-      @outdatedness_rules_summary = DDTelemetry::Summary.new
-      @filters_summary = DDTelemetry::Summary.new
-      @load_stores_summary = DDTelemetry::Summary.new
+      @stages_summary = DDMetrics::Summary.new
+      @phases_summary = DDMetrics::Summary.new
+      @outdatedness_rules_summary = DDMetrics::Summary.new
+      @filters_summary = DDMetrics::Summary.new
+      @load_stores_summary = DDMetrics::Summary.new
     end
 
     # @see Listener#start
     def start
       on(:stage_ran) do |duration, klass|
-        @stages_summary.observe(duration, klass.to_s.sub(/.*::/, ''))
+        @stages_summary.observe(duration, name: klass.to_s.sub(/.*::/, ''))
       end
 
       on(:outdatedness_rule_ran) do |duration, klass|
-        @outdatedness_rules_summary.observe(duration, klass.to_s.sub(/.*::/, ''))
+        @outdatedness_rules_summary.observe(duration, name: klass.to_s.sub(/.*::/, ''))
       end
 
       filter_stopwatches = {}
 
       on(:filtering_started) do |rep, _filter_name|
         stopwatch_stack = filter_stopwatches.fetch(rep) { filter_stopwatches[rep] = [] }
-        stopwatch_stack << DDTelemetry::Stopwatch.new
+        stopwatch_stack << DDMetrics::Stopwatch.new
         stopwatch_stack.last.start
       end
 
       on(:filtering_ended) do |rep, filter_name|
         stopwatch = filter_stopwatches.fetch(rep).pop
         stopwatch.stop
 
-        @filters_summary.observe(stopwatch.duration, filter_name.to_s)
+        @filters_summary.observe(stopwatch.duration, name: filter_name.to_s)
       end
 
       on(:store_loaded) do |duration, klass|
-        @load_stores_summary.observe(duration, klass.to_s)
+        @load_stores_summary.observe(duration, name: klass.to_s)
       end
 
       on(:compilation_suspended) do |rep, _exception|
@@ -64,14 +64,14 @@ def start
 
       on(:phase_started) do |phase_name, rep|
         stopwatches = phase_stopwatches.fetch(rep) { phase_stopwatches[rep] = {} }
-        stopwatches[phase_name] = DDTelemetry::Stopwatch.new.tap(&:start)
+        stopwatches[phase_name] = DDMetrics::Stopwatch.new.tap(&:start)
       end
 
       on(:phase_ended) do |phase_name, rep|
         stopwatch = phase_stopwatches.fetch(rep).fetch(phase_name)
         stopwatch.stop
 
-        @phases_summary.observe(stopwatch.duration, phase_name)
+        @phases_summary.observe(stopwatch.duration, name: phase_name)
       end
 
       on(:phase_yielded) do |phase_name, rep|
@@ -88,7 +88,7 @@ def start
         stopwatch = phase_stopwatches.fetch(rep).fetch(phase_name)
         stopwatch.stop if stopwatch.running?
 
-        @phases_summary.observe(stopwatch.duration, phase_name)
+        @phases_summary.observe(stopwatch.duration, name: phase_name)
       end
     end
 
@@ -103,7 +103,9 @@ def stop
     def table_for_summary(name, summary)
       headers = [name.to_s, 'count', 'min', '.50', '.90', '.95', 'max', 'tot']
 
-      rows = summary.map do |filter_name, stats|
+      rows = summary.map do |label, stats|
+        name = label.fetch(:name)
+
         count = stats.count
         min   = stats.min
         p50   = stats.quantile(0.50)
@@ -112,7 +114,7 @@ def table_for_summary(name, summary)
         tot   = stats.sum
         max   = stats.max
 
-        [filter_name, count.to_s] + [min, p50, p90, p95, max, tot].map { |r| "#{format('%4.2f', r)}s" }
+        [name, count.to_s] + [min, p50, p90, p95, max, tot].map { |r| "#{format('%4.2f', r)}s" }
       end
 
       [headers] + rows
@@ -121,8 +123,9 @@ def table_for_summary(name, summary)
     def table_for_summary_durations(name, summary)
       headers = [name.to_s, 'tot']
 
-      rows = summary.map do |stage_name, stats|
-        [stage_name, "#{format('%4.2f', stats.sum)}s"]
+      rows = summary.map do |label, stats|
+        name = label.fetch(:name)
+        [name, "#{format('%4.2f', stats.sum)}s"]
       end
 
       [headers] + rows
@@ -134,7 +137,7 @@ def print_profiling_feedback
       print_table_for_summary_duration(:stages, @stages_summary) if Nanoc::CLI.verbosity >= 2
       print_table_for_summary(:outdatedness_rules, @outdatedness_rules_summary) if Nanoc::CLI.verbosity >= 2
       print_table_for_summary_duration(:load_stores, @load_stores_summary) if Nanoc::CLI.verbosity >= 2
-      DDMemoize.print_telemetry if Nanoc::CLI.verbosity >= 2
+      DDMemoize.print_metrics if Nanoc::CLI.verbosity >= 2
     end
 
     def print_table_for_summary(name, summary)
@@ -152,7 +155,7 @@ def print_table_for_summary_duration(name, summary)
     end
 
     def print_table(rows)
-      puts DDTelemetry::Table.new(rows).to_s
+      puts DDMetrics::Table.new(rows).to_s
     end
   end
 end

nanoc/nanoc.gemspec

@@ -23,9 +23,9 @@ Gem::Specification.new do |s|
 
   s.add_runtime_dependency('addressable', '~> 2.5')
   s.add_runtime_dependency('cri', '~> 2.8')
-  s.add_runtime_dependency('ddmemoize', '= 1.0.0a3') # TODO: upgrade
+  s.add_runtime_dependency('ddmemoize', '= 1.0.0rc1') # TODO: upgrade
+  s.add_runtime_dependency('ddmetrics', '= 1.0.0rc1') # TODO: upgrade
   s.add_runtime_dependency('ddplugin', '~> 1.0')
-  s.add_runtime_dependency('ddtelemetry', '= 1.0.0a2') # TODO: upgrade
   s.add_runtime_dependency('hamster', '~> 3.0')
   s.add_runtime_dependency('ref', '~> 2.0')
   s.add_runtime_dependency('slow_enumerator_tools', '~> 1.0')

nanoc/spec/nanoc/cli/commands/compile/timing_recorder_spec.rb

@@ -51,11 +51,11 @@
     Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
     Nanoc::Int::NotificationCenter.post(:filtering_ended, rep, :erb)
 
-    expect(listener.filters_summary.get('erb').min).to eq(1.00)
-    expect(listener.filters_summary.get('erb').avg).to eq(1.00)
-    expect(listener.filters_summary.get('erb').max).to eq(1.00)
-    expect(listener.filters_summary.get('erb').sum).to eq(1.00)
-    expect(listener.filters_summary.get('erb').count).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').min).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').avg).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').max).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').sum).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').count).to eq(1.00)
   end
 
   it 'records multiple from filtering_started to filtering_ended' do
@@ -68,11 +68,11 @@
     Timecop.freeze(Time.local(2008, 9, 1, 10, 14, 3))
     Nanoc::Int::NotificationCenter.post(:filtering_ended, rep, :erb)
 
-    expect(listener.filters_summary.get('erb').min).to eq(1.00)
-    expect(listener.filters_summary.get('erb').avg).to eq(1.50)
-    expect(listener.filters_summary.get('erb').max).to eq(2.00)
-    expect(listener.filters_summary.get('erb').sum).to eq(3.00)
-    expect(listener.filters_summary.get('erb').count).to eq(2.00)
+    expect(listener.filters_summary.get(name: 'erb').min).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').avg).to eq(1.50)
+    expect(listener.filters_summary.get(name: 'erb').max).to eq(2.00)
+    expect(listener.filters_summary.get(name: 'erb').sum).to eq(3.00)
+    expect(listener.filters_summary.get(name: 'erb').count).to eq(2.00)
   end
 
   it 'records filters in nested filtering_started/filtering_ended' do
@@ -85,17 +85,17 @@
     Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 6))
     Nanoc::Int::NotificationCenter.post(:filtering_ended, rep, :outer)
 
-    expect(listener.filters_summary.get('inner').min).to eq(2.00)
-    expect(listener.filters_summary.get('inner').avg).to eq(2.00)
-    expect(listener.filters_summary.get('inner').max).to eq(2.00)
-    expect(listener.filters_summary.get('inner').sum).to eq(2.00)
-    expect(listener.filters_summary.get('inner').count).to eq(1.00)
-
-    expect(listener.filters_summary.get('outer').min).to eq(6.00)
-    expect(listener.filters_summary.get('outer').avg).to eq(6.00)
-    expect(listener.filters_summary.get('outer').max).to eq(6.00)
-    expect(listener.filters_summary.get('outer').sum).to eq(6.00)
-    expect(listener.filters_summary.get('outer').count).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'inner').min).to eq(2.00)
+    expect(listener.filters_summary.get(name: 'inner').avg).to eq(2.00)
+    expect(listener.filters_summary.get(name: 'inner').max).to eq(2.00)
+    expect(listener.filters_summary.get(name: 'inner').sum).to eq(2.00)
+    expect(listener.filters_summary.get(name: 'inner').count).to eq(1.00)
+
+    expect(listener.filters_summary.get(name: 'outer').min).to eq(6.00)
+    expect(listener.filters_summary.get(name: 'outer').avg).to eq(6.00)
+    expect(listener.filters_summary.get(name: 'outer').max).to eq(6.00)
+    expect(listener.filters_summary.get(name: 'outer').sum).to eq(6.00)
+    expect(listener.filters_summary.get(name: 'outer').count).to eq(1.00)
   end
 
   it 'pauses outer stopwatch when suspended' do
@@ -112,11 +112,11 @@
     Nanoc::Int::NotificationCenter.post(:filtering_ended, rep, :inner)
     Nanoc::Int::NotificationCenter.post(:filtering_ended, rep, :outer)
 
-    expect(listener.filters_summary.get('outer').min).to eq(7.00)
-    expect(listener.filters_summary.get('outer').avg).to eq(7.00)
-    expect(listener.filters_summary.get('outer').max).to eq(7.00)
-    expect(listener.filters_summary.get('outer').sum).to eq(7.00)
-    expect(listener.filters_summary.get('outer').count).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'outer').min).to eq(7.00)
+    expect(listener.filters_summary.get(name: 'outer').avg).to eq(7.00)
+    expect(listener.filters_summary.get(name: 'outer').max).to eq(7.00)
+    expect(listener.filters_summary.get(name: 'outer').sum).to eq(7.00)
+    expect(listener.filters_summary.get(name: 'outer').count).to eq(1.00)
   end
 
   it 'records single from filtering_started over compilation_{suspended,started} to filtering_ended' do
@@ -130,11 +130,11 @@
     Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 7))
     Nanoc::Int::NotificationCenter.post(:filtering_ended, rep, :erb)
 
-    expect(listener.filters_summary.get('erb').min).to eq(5.00)
-    expect(listener.filters_summary.get('erb').avg).to eq(5.00)
-    expect(listener.filters_summary.get('erb').max).to eq(5.00)
-    expect(listener.filters_summary.get('erb').sum).to eq(5.00)
-    expect(listener.filters_summary.get('erb').count).to eq(1.00)
+    expect(listener.filters_summary.get(name: 'erb').min).to eq(5.00)
+    expect(listener.filters_summary.get(name: 'erb').avg).to eq(5.00)
+    expect(listener.filters_summary.get(name: 'erb').max).to eq(5.00)
+    expect(listener.filters_summary.get(name: 'erb').sum).to eq(5.00)
+    expect(listener.filters_summary.get(name: 'erb').count).to eq(1.00)
   end
 
   it 'records single phase start+stop' do
@@ -143,11 +143,11 @@
     Timecop.freeze(Time.local(2008, 9, 1, 10, 5, 1))
     Nanoc::Int::NotificationCenter.post(:phase_ended, 'donkey', rep)
 
-    expect(listener.phases_summary.get('donkey').min).to eq(1.00)
-    expect(listener.phases_summary.get('donkey').avg).to eq(1.00)
-    expect(listener.phases_summary.get('donkey').max).to eq(1.00)
-    expect(listener.phases_summary.get('donkey').sum).to eq(1.00)
-    expect(listener.phases_summary.get('donkey').count).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').min).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').avg).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').max).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').sum).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').count).to eq(1.00)
   end
 
   it 'records multiple phase start+stop' do
@@ -160,11 +160,11 @@
     Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 2))
     Nanoc::Int::NotificationCenter.post(:phase_ended, 'donkey', rep)
 
-    expect(listener.phases_summary.get('donkey').min).to eq(1.00)
-    expect(listener.phases_summary.get('donkey').avg).to eq(1.50)
-    expect(listener.phases_summary.get('donkey').max).to eq(2.00)
-    expect(listener.phases_summary.get('donkey').sum).to eq(3.00)
-    expect(listener.phases_summary.get('donkey').count).to eq(2.00)
+    expect(listener.phases_summary.get(name: 'donkey').min).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').avg).to eq(1.50)
+    expect(listener.phases_summary.get(name: 'donkey').max).to eq(2.00)
+    expect(listener.phases_summary.get(name: 'donkey').sum).to eq(3.00)
+    expect(listener.phases_summary.get(name: 'donkey').count).to eq(2.00)
   end
 
   it 'records single phase start+yield+resume+stop' do
@@ -177,11 +177,11 @@
     Timecop.freeze(Time.local(2008, 9, 1, 11, 6, 2))
     Nanoc::Int::NotificationCenter.post(:phase_ended, 'donkey', rep)
 
-    expect(listener.phases_summary.get('donkey').min).to eq(3.00)
-    expect(listener.phases_summary.get('donkey').avg).to eq(3.00)
-    expect(listener.phases_summary.get('donkey').max).to eq(3.00)
-    expect(listener.phases_summary.get('donkey').sum).to eq(3.00)
-    expect(listener.phases_summary.get('donkey').count).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').min).to eq(3.00)
+    expect(listener.phases_summary.get(name: 'donkey').avg).to eq(3.00)
+    expect(listener.phases_summary.get(name: 'donkey').max).to eq(3.00)
+    expect(listener.phases_summary.get(name: 'donkey').sum).to eq(3.00)
+    expect(listener.phases_summary.get(name: 'donkey').count).to eq(1.00)
   end
 
   it 'records single phase start+yield+abort+start+stop' do
@@ -196,18 +196,18 @@
     Timecop.freeze(Time.local(2008, 9, 1, 12, 7, 5))
     Nanoc::Int::NotificationCenter.post(:phase_ended, 'donkey', rep)
 
-    expect(listener.phases_summary.get('donkey').min).to eq(1.00)
-    expect(listener.phases_summary.get('donkey').avg).to eq(2.00)
-    expect(listener.phases_summary.get('donkey').max).to eq(3.00)
-    expect(listener.phases_summary.get('donkey').sum).to eq(4.00)
-    expect(listener.phases_summary.get('donkey').count).to eq(2.00)
+    expect(listener.phases_summary.get(name: 'donkey').min).to eq(1.00)
+    expect(listener.phases_summary.get(name: 'donkey').avg).to eq(2.00)
+    expect(listener.phases_summary.get(name: 'donkey').max).to eq(3.00)
+    expect(listener.phases_summary.get(name: 'donkey').sum).to eq(4.00)
+    expect(listener.phases_summary.get(name: 'donkey').count).to eq(2.00)
   end
 
   it 'records stage duration' do
     Nanoc::Int::NotificationCenter.post(:stage_ran, 1.23, 'donkey_stage')
 
-    expect(listener.stages_summary.get('donkey_stage').sum).to eq(1.23)
-    expect(listener.stages_summary.get('donkey_stage').count).to eq(1)
+    expect(listener.stages_summary.get(name: 'donkey_stage').sum).to eq(1.23)
+    expect(listener.stages_summary.get(name: 'donkey_stage').count).to eq(1)
   end
 
   it 'prints stage durations' do
@@ -227,22 +227,22 @@
   it 'records single outdatedness rule duration' do
     Nanoc::Int::NotificationCenter.post(:outdatedness_rule_ran, 1.0, Nanoc::Int::OutdatednessRules::CodeSnippetsModified)
 
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').min).to eq(1.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').avg).to eq(1.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').max).to eq(1.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').sum).to eq(1.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').count).to eq(1.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').min).to eq(1.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').avg).to eq(1.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').max).to eq(1.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').sum).to eq(1.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').count).to eq(1.00)
   end
 
   it 'records multiple outdatedness rule duration' do
     Nanoc::Int::NotificationCenter.post(:outdatedness_rule_ran, 1.0, Nanoc::Int::OutdatednessRules::CodeSnippetsModified)
     Nanoc::Int::NotificationCenter.post(:outdatedness_rule_ran, 3.0, Nanoc::Int::OutdatednessRules::CodeSnippetsModified)
 
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').min).to eq(1.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').avg).to eq(2.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').max).to eq(3.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').sum).to eq(4.00)
-    expect(listener.outdatedness_rules_summary.get('CodeSnippetsModified').count).to eq(2.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').min).to eq(1.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').avg).to eq(2.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').max).to eq(3.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').sum).to eq(4.00)
+    expect(listener.outdatedness_rules_summary.get(name: 'CodeSnippetsModified').count).to eq(2.00)
   end
 
   it 'prints load store durations' do