From 1987656d93349b7af2b361b908f8afe69c5dd2e4 Mon Sep 17 00:00:00 2001 From: Elena Tanasoiu Date: Tue, 10 Dec 2024 17:23:14 +0000 Subject: [PATCH 1/4] Report CPU Time alongside Wall Time We'd like to be able to quantify CPU time consumed while executing the candidate and control blocks during science experiments. Changes include: - Added `cpu_time` attribute to `Scientist::Observation`. - Refactored initialization to capture both start/end times for wall time and CPU time. - Updated tests to include CPU-intensive work so we can verify we're recording CPU time correctly. This allows us to track cpu time more precisely when making improvements. --- lib/scientist/observation.rb | 25 ++++++++++++++++++++++--- test/scientist/experiment_test.rb | 30 +++++++++++++++++++++++++----- test/scientist/observation_test.rb | 7 ++++++- 3 files changed, 53 insertions(+), 9 deletions(-) diff --git a/lib/scientist/observation.rb b/lib/scientist/observation.rb index eb55115..df948e0 100644 --- a/lib/scientist/observation.rb +++ b/lib/scientist/observation.rb @@ -20,19 +20,29 @@ 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 + @duration = fabricated_duration["duration"] + @cpu_time = fabricated_duration["cpu_time"] + 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 +99,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..e9468e7 100644 --- a/test/scientist/experiment_test.rb +++ b/test/scientist/experiment_test.rb @@ -674,27 +674,47 @@ def @ex.enabled? it "allows a user to provide fabricated durations for testing purposes" do @ex.use { true } @ex.try { true } - @ex.fabricate_durations_for_testing_purposes( "control" => 0.5, "candidate" => 1.0 ) - + @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" do @ex.use { true } - @ex.try { sleep 0.1; true } - @ex.fabricate_durations_for_testing_purposes( "control" => 0.5 ) - + @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 From cb642e8b4c7880af813b2ae15250b8c512c74086 Mon Sep 17 00:00:00 2001 From: Elena Tanasoiu Date: Tue, 10 Dec 2024 17:32:54 +0000 Subject: [PATCH 2/4] Update README to mention CPU time tracking --- README.md | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index fc264ec..1914cd9 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. @@ -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._ From b2311bcd7587a07d4671eb6271f7961837d404b8 Mon Sep 17 00:00:00 2001 From: Elena Tanasoiu Date: Fri, 13 Dec 2024 16:50:22 +0000 Subject: [PATCH 3/4] Make the change backwards-compatible This supports both the old version (single value) and new version (hash-based). I've added back the tests from the old version to check that the code stills works when we provide a single value. I've also adapted the README a bit to explain both versions. --- README.md | 24 +++++++++++++++++++++--- lib/scientist/observation.rb | 5 ++++- test/scientist/experiment_test.rb | 30 ++++++++++++++++++++++++++++-- 3 files changed, 53 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index 1914cd9..e01e8ec 100644 --- a/README.md +++ b/README.md @@ -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| @@ -550,7 +550,25 @@ 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` and `Scientist::Observation#cpu_time` 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. This can be done using either the old version (single value) or the new version (hash-based) to include both duration and cpu_time. + +##### Old version (Single Value) + +In the old version, you can provide a single value for the duration: + +```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 ) +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. + +##### New version (Hash-based) + +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| diff --git a/lib/scientist/observation.rb b/lib/scientist/observation.rb index df948e0..2b13903 100644 --- a/lib/scientist/observation.rb +++ b/lib/scientist/observation.rb @@ -35,9 +35,12 @@ def initialize(name, experiment, fabricated_duration: nil, &block) @exception = e end - if fabricated_duration + 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 diff --git a/test/scientist/experiment_test.rb b/test/scientist/experiment_test.rb index e9468e7..434e673 100644 --- a/test/scientist/experiment_test.rb +++ b/test/scientist/experiment_test.rb @@ -671,7 +671,20 @@ 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 ) + + @ex.run + + cont = @ex.published_result.control + cand = @ex.published_result.candidates.first + assert_in_delta 0.5, cont.duration, 0.01 + assert_in_delta 1.0, cand.duration, 0.01 + end + + 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({ @@ -692,7 +705,20 @@ def @ex.enabled? assert_equal 0.9, cand.cpu_time end - it "returns actual durations if fabricated ones are omitted for some blocks" do + 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 ) + + @ex.run + + cont = @ex.published_result.control + cand = @ex.published_result.candidates.first + 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 From 4a454123805810bb6b910a03066ace760f6316c6 Mon Sep 17 00:00:00 2001 From: Elena Tanasoiu Date: Fri, 13 Dec 2024 22:52:07 +0000 Subject: [PATCH 4/4] Only explain new version in the README --- README.md | 20 +------------------- 1 file changed, 1 insertion(+), 19 deletions(-) diff --git a/README.md b/README.md index e01e8ec..e076498 100644 --- a/README.md +++ b/README.md @@ -550,25 +550,7 @@ 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. This can be done using either the old version (single value) or the new version (hash-based) to include both duration and cpu_time. - -##### Old version (Single Value) - -In the old version, you can provide a single value for the duration: - -```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 ) -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. - -##### New version (Hash-based) - -Scientist will report these in `Scientist::Observation#duration` and `Scientist::Observation#cpu_time` 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|