Skip to content

Commit

Permalink
Merge pull request #275 from elenatanasoiu/elena/add-cpu-time
Browse files Browse the repository at this point in the history
Report CPU Time alongside Wall Time
  • Loading branch information
zerowidth authored Dec 16, 2024
2 parents b15ceeb + 4a45412 commit fdd09d0
Show file tree
Hide file tree
Showing 4 changed files with 97 additions and 12 deletions.
24 changes: 18 additions & 6 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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|
Expand Down Expand Up @@ -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"
Expand Down Expand Up @@ -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._

Expand Down
28 changes: 25 additions & 3 deletions lib/scientist/observation.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
50 changes: 48 additions & 2 deletions test/scientist/experiment_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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 )
Expand All @@ -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 )
Expand All @@ -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
7 changes: 6 additions & 1 deletion test/scientist/observation_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit fdd09d0

Please sign in to comment.