diff --git a/README.md b/README.md index fc264ec..e076498 100644 --- a/README.md +++ b/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,7 +121,7 @@ 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 @@ -129,7 +129,7 @@ class MyWidget 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._ diff --git a/lib/scientist/observation.rb b/lib/scientist/observation.rb index eb55115..2b13903 100644 --- a/lib/scientist/observation.rb +++ b/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 diff --git a/test/scientist/experiment_test.rb b/test/scientist/experiment_test.rb index e155043..434e673 100644 --- a/test/scientist/experiment_test.rb +++ b/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 diff --git a/test/scientist/observation_test.rb b/test/scientist/observation_test.rb index b788663..79455d3 100644 --- a/test/scientist/observation_test.rb +++ b/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