Merge pull request #275 from elenatanasoiu/elena/add-cpu-time

Report CPU Time alongside Wall Time

Author: zerowidth

README.md

@@ -24,7 +24,7 @@ Wrap a `use` block around the code's original behavior, and wrap `try` around th
 
 * It decides whether or not to run the `try` block,
 * Randomizes the order in which `use` and `try` blocks are run,
-* Measures the durations of all behaviors in seconds,
+* Measures the wall time and cpu time of all behaviors in seconds,
 * Compares the result of `try` to the result of `use`,
 * Swallow and record exceptions raised in the `try` block when overriding `raised`, and
 * Publishes all this information.
@@ -121,15 +121,15 @@ class MyWidget
       e.try { UserService.slug_from_login login }  # returns String instance or ArgumentError
 
       compare_error_message_and_class = -> (control, candidate) do
-        control.class == candidate.class && 
+        control.class == candidate.class &&
         control.message == candidate.message
       end
 
       compare_argument_errors = -> (control, candidate) do
         control.class == ArgumentError &&
         candidate.class == ArgumentError &&
         control.message.start_with?("Input has invalid characters") &&
-        candidate.message.start_with?("Invalid characters in input") 
+        candidate.message.start_with?("Invalid characters in input")
       end
 
       e.compare_errors do |control, candidate|
@@ -334,11 +334,18 @@ class MyExperiment
 
   def publish(result)
 
+    # Wall time
     # Store the timing for the control value,
     $statsd.timing "science.#{name}.control", result.control.duration
     # for the candidate (only the first, see "Breaking the rules" below,
     $statsd.timing "science.#{name}.candidate", result.candidates.first.duration
 
+    # CPU time
+    # Store the timing for the control value,
+    $statsd.timing "science.cpu.#{name}.control", result.control.cpu_time
+    # for the candidate (only the first, see "Breaking the rules" below,
+    $statsd.timing "science.cpu.#{name}.candidate", result.candidates.first.cpu_time
+
     # and counts for match/ignore/mismatch:
     if result.matched?
       $statsd.increment "science.#{name}.matched"
@@ -543,17 +550,22 @@ end
 
 #### Providing fake timing data
 
-If you're writing tests that depend on specific timing values, you can provide canned durations using the `fabricate_durations_for_testing_purposes` method, and Scientist will report these in `Scientist::Observation#duration` instead of the actual execution times.
+If you're writing tests that depend on specific timing values, you can provide canned durations using the `fabricate_durations_for_testing_purposes` method, and Scientist will report these in `Scientist::Observation#duration` and `Scientist::Observation#cpu_time` instead of the actual execution times.
 
 ```ruby
 science "absolutely-nothing-suspicious-happening-here" do |e|
   e.use { ... } # "control"
   e.try { ... } # "candidate"
-  e.fabricate_durations_for_testing_purposes( "control" => 1.0, "candidate" => 0.5 )
+  e.fabricate_durations_for_testing_purposes({
+    "control" => { "duration" => 1.0, "cpu_time" => 0.9 },
+    "candidate" => { "duration" => 0.5, "cpu_time" => 0.4 }
+  })
 end
 ```
 
-`fabricate_durations_for_testing_purposes` takes a Hash of duration values, keyed by behavior names.  (By default, Scientist uses `"control"` and `"candidate"`, but if you override these as shown in [Trying more than one thing](#trying-more-than-one-thing) or [No control, just candidates](#no-control-just-candidates), use matching names here.)  If a name is not provided, the actual execution time will be reported instead.
+`fabricate_durations_for_testing_purposes` takes a Hash of duration & cpu_time values, keyed by behavior names.  (By default, Scientist uses `"control"` and `"candidate"`, but if you override these as shown in [Trying more than one thing](#trying-more-than-one-thing) or [No control, just candidates](#no-control-just-candidates), use matching names here.)  If a name is not provided, the actual execution time will be reported instead.
+
+We should mention these durations will be used both for the `duration` field and the `cpu_time` field.
 
 _Like `Scientist::Experiment#cleaner`, this probably won't come up in normal usage.  It's here to make it easier to test code that extends Scientist._
 

lib/scientist/observation.rb

@@ -20,19 +20,32 @@ class Scientist::Observation
   # The Float seconds elapsed.
   attr_reader :duration
 
+  # The Float CPU time elapsed, in seconds
+  attr_reader :cpu_time
+
   def initialize(name, experiment, fabricated_duration: nil, &block)
     @name       = name
     @experiment = experiment
 
-    starting = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second) unless fabricated_duration
+    start_wall_time, start_cpu_time = capture_times unless fabricated_duration
+
     begin
       @value = block.call
     rescue *RESCUES => e
       @exception = e
     end
 
-    @duration = fabricated_duration ||
-      Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second) - starting
+    if fabricated_duration.is_a?(Hash)
+      @duration = fabricated_duration["duration"]
+      @cpu_time = fabricated_duration["cpu_time"]
+    elsif fabricated_duration
+      @duration = fabricated_duration
+      @cpu_time = 0.0 # setting a default value
+    else
+      end_wall_time, end_cpu_time = capture_times
+      @duration = end_wall_time - start_wall_time
+      @cpu_time = end_cpu_time - start_cpu_time
+    end
 
     freeze
   end
@@ -89,4 +102,13 @@ def hash
   def raised?
     !exception.nil?
   end
+
+  private
+
+  def capture_times
+    [
+      Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second),
+      Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :float_second)
+    ]
+  end
 end

test/scientist/experiment_test.rb

@@ -671,7 +671,7 @@ def @ex.enabled?
   end
 
   describe "testing hooks for extending code" do
-    it "allows a user to provide fabricated durations for testing purposes" do
+    it "allows a user to provide fabricated durations for testing purposes (old version)" do
       @ex.use { true }
       @ex.try { true }
       @ex.fabricate_durations_for_testing_purposes( "control" => 0.5, "candidate" => 1.0 )
@@ -684,7 +684,28 @@ def @ex.enabled?
       assert_in_delta 1.0, cand.duration, 0.01
     end
 
-    it "returns actual durations if fabricated ones are omitted for some blocks" do
+    it "allows a user to provide fabricated durations for testing purposes (new version)" do
+      @ex.use { true }
+      @ex.try { true }
+      @ex.fabricate_durations_for_testing_purposes({
+        "control" => { "duration" => 0.5, "cpu_time" => 0.4 },
+        "candidate" => { "duration" => 1.0, "cpu_time" => 0.9 }
+      })
+      @ex.run
+
+      cont = @ex.published_result.control
+      cand = @ex.published_result.candidates.first
+
+      # Wall Time
+      assert_in_delta 0.5, cont.duration, 0.01
+      assert_in_delta 1.0, cand.duration, 0.01
+
+      # CPU Time
+      assert_equal 0.4, cont.cpu_time
+      assert_equal 0.9, cand.cpu_time
+    end
+
+    it "returns actual durations if fabricated ones are omitted for some blocks (old version)" do
       @ex.use { true }
       @ex.try { sleep 0.1; true }
       @ex.fabricate_durations_for_testing_purposes( "control" => 0.5 )
@@ -696,5 +717,30 @@ def @ex.enabled?
       assert_in_delta 0.5, cont.duration, 0.01
       assert_in_delta 0.1, cand.duration, 0.01
     end
+
+    it "returns actual durations if fabricated ones are omitted for some blocks (new version)" do
+      @ex.use { true }
+      @ex.try do
+        start_time = Time.now
+        while Time.now - start_time < 0.1
+          # Perform some CPU-intensive work
+          (1..1000).each { |i| i * i }
+        end
+        true
+      end
+      @ex.fabricate_durations_for_testing_purposes({ "control" => { "duration" => 0.5, "cpu_time" => 0.4 }})
+      @ex.run
+
+      cont = @ex.published_result.control
+      cand = @ex.published_result.candidates.first
+
+      # Fabricated durations
+      assert_in_delta 0.5, cont.duration, 0.01
+      assert_in_delta 0.4, cont.cpu_time, 0.01
+
+      # Measured durations
+      assert_in_delta 0.1, cand.duration, 0.01
+      assert_in_delta 0.1, cand.cpu_time, 0.01
+    end
   end
 end

test/scientist/observation_test.rb

@@ -6,13 +6,18 @@
 
   it "observes and records the execution of a block" do
     ob = Scientist::Observation.new("test", @experiment) do
-      sleep 0.1
+      start_time = Time.now
+      while Time.now - start_time < 0.1
+        # Perform some CPU-intensive work
+        (1..1000).each { |i| i * i }
+      end
       "ret"
     end
 
     assert_equal "ret", ob.value
     refute ob.raised?
     assert_in_delta 0.1, ob.duration, 0.01
+    assert_in_delta 0.1, ob.cpu_time, 0.01
   end
 
   it "stashes exceptions" do