diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 095758d..0930434 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -24,8 +24,9 @@ jobs: - "3.0" - "3.1" - "3.2" + - "3.3" steps: - - uses: actions/checkout@v3 + - uses: actions/checkout@v4 - uses: ruby/setup-ruby@v1 with: ruby-version: ${{ matrix.ruby_version }} diff --git a/README.md b/README.md index b64675e..e076498 100644 --- a/README.md +++ b/README.md @@ -12,7 +12,7 @@ require "scientist" class MyWidget def allows?(user) experiment = Scientist::Default.new "widget-permissions" - experiment.use { model.check_user?(user).valid? } # old way + experiment.use { model.check_user(user).valid? } # old way experiment.try { user.can?(:read, model) } # new way experiment.run @@ -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| @@ -241,6 +241,19 @@ end Note that the `#clean` method will discard the previous cleaner block if you call it again. If for some reason you need to access the currently configured cleaner block, `Scientist::Experiment#cleaner` will return the block without further ado. _(This probably won't come up in normal usage, but comes in handy if you're writing, say, a custom experiment runner that provides default cleaners.)_ +The `#clean` method will not be used for comparison of the results, so in the following example it is not possible to remove the `#compare` method without the experiment failing: + +```ruby +def user_ids + science "user_ids" do + e.use { [1,2,3] } + e.try { [1,3,2] } + e.clean { |value| value.sort } + e.compare { |a, b| a.sort == b.sort } + end +end +``` + ### Ignoring mismatches During the early stages of an experiment, it's possible that some of your code will always generate a mismatch for reasons you know and understand but haven't yet fixed. Instead of these known cases always showing up as mismatches in your metrics or analysis, you can tell an experiment whether or not to ignore a mismatch using the `ignore` method. You may include more than one block if needed: @@ -321,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" @@ -530,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/doc/changelog.md b/doc/changelog.md index c32a272..978fde0 100644 --- a/doc/changelog.md +++ b/doc/changelog.md @@ -1,5 +1,49 @@ # Changes +## v1.6.5 (16 December 2024) + +- New: measure CPU time alongside wall time for experiments #275 + +## v1.6.4 (5 April 2023) + +- New: GitHub Actions for CI #171 +- New: add ruby 3.1 support #175 +- Fix: `compare_errors` in docs #178 +- Fix: remove outdated travis configs #179 +- Fix: typos #191 +- New: add support for `after_run` blocks #211 + +## v1.6.3 (9 December 2021) + +- Fix: improve marshaling implementation #169 + +## v1.6.2 (4 November 2021) + +- New: make `MismatchError` marshalable #168 + +## v1.6.1 (22 October 2021) + +- Fix: moving supported ruby versions from <=2.3 to >=2.6 #150 +- Fix: update docs to explain timeout handling #159 +- New: add support for comparing errors #77 + +## v1.6.0 (8 March 2021) + +- Fix: clarify unit for observations #124 +- New: enable support for truffleruby #143 +- Fix: don't default experiment when included in a module #144 + +## v1.5.0 (8 September 2020) + +- Fix: clearer explanation of exception handling #110 +- Fix: remove unused attribute from `Scientist::Observation` #119 +- New: Added internal extension point for generating experinet results #121 +- New: Add `Scientist::Experiment.register` helper #104 + +## v1.4.0 (20 September 2019) + +- New: Make `MismatchError` a base `Exception` #107 + ## v1.3.0 (2 April 2019) - New: Drop support for ruby <2.3 diff --git a/lib/scientist/experiment.rb b/lib/scientist/experiment.rb index 7512c0b..591b3a0 100644 --- a/lib/scientist/experiment.rb +++ b/lib/scientist/experiment.rb @@ -345,7 +345,7 @@ def marshal_dump [@name, @result, @raise_on_mismatches] end - def marshal_load + def marshal_load(array) @name, @result, @raise_on_mismatches = array end end 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/lib/scientist/version.rb b/lib/scientist/version.rb index 6f44cc0..261500f 100644 --- a/lib/scientist/version.rb +++ b/lib/scientist/version.rb @@ -1,3 +1,3 @@ module Scientist - VERSION = '1.6.4' + VERSION = '1.6.5' end diff --git a/test/scientist/experiment_test.rb b/test/scientist/experiment_test.rb index 1452d9c..434e673 100644 --- a/test/scientist/experiment_test.rb +++ b/test/scientist/experiment_test.rb @@ -512,6 +512,10 @@ def @ex.raised(op, exception) assert_kind_of(String, Marshal.dump(mismatch)) end + it "can be marshal loaded" do + assert_kind_of(Fake, Marshal.load(Marshal.dump(@ex))) + end + describe "#raise_on_mismatches?" do it "raises when there is a mismatch if the experiment instance's raise on mismatches is enabled" do Fake.raise_on_mismatches = false @@ -667,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 ) @@ -680,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 ) @@ -692,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