Skip to content

Commit 1987656

Browse files
committed
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.
1 parent b15ceeb commit 1987656

File tree

3 files changed

+53
-9
lines changed

3 files changed

+53
-9
lines changed

lib/scientist/observation.rb

Lines changed: 22 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -20,19 +20,29 @@ class Scientist::Observation
2020
# The Float seconds elapsed.
2121
attr_reader :duration
2222

23+
# The Float CPU time elapsed, in seconds
24+
attr_reader :cpu_time
25+
2326
def initialize(name, experiment, fabricated_duration: nil, &block)
2427
@name = name
2528
@experiment = experiment
2629

27-
starting = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second) unless fabricated_duration
30+
start_wall_time, start_cpu_time = capture_times unless fabricated_duration
31+
2832
begin
2933
@value = block.call
3034
rescue *RESCUES => e
3135
@exception = e
3236
end
3337

34-
@duration = fabricated_duration ||
35-
Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second) - starting
38+
if fabricated_duration
39+
@duration = fabricated_duration["duration"]
40+
@cpu_time = fabricated_duration["cpu_time"]
41+
else
42+
end_wall_time, end_cpu_time = capture_times
43+
@duration = end_wall_time - start_wall_time
44+
@cpu_time = end_cpu_time - start_cpu_time
45+
end
3646

3747
freeze
3848
end
@@ -89,4 +99,13 @@ def hash
8999
def raised?
90100
!exception.nil?
91101
end
102+
103+
private
104+
105+
def capture_times
106+
[
107+
Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second),
108+
Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :float_second)
109+
]
110+
end
92111
end

test/scientist/experiment_test.rb

Lines changed: 25 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -674,27 +674,47 @@ def @ex.enabled?
674674
it "allows a user to provide fabricated durations for testing purposes" do
675675
@ex.use { true }
676676
@ex.try { true }
677-
@ex.fabricate_durations_for_testing_purposes( "control" => 0.5, "candidate" => 1.0 )
678-
677+
@ex.fabricate_durations_for_testing_purposes({
678+
"control" => { "duration" => 0.5, "cpu_time" => 0.4 },
679+
"candidate" => { "duration" => 1.0, "cpu_time" => 0.9 }
680+
})
679681
@ex.run
680682

681683
cont = @ex.published_result.control
682684
cand = @ex.published_result.candidates.first
685+
686+
# Wall Time
683687
assert_in_delta 0.5, cont.duration, 0.01
684688
assert_in_delta 1.0, cand.duration, 0.01
689+
690+
# CPU Time
691+
assert_equal 0.4, cont.cpu_time
692+
assert_equal 0.9, cand.cpu_time
685693
end
686694

687695
it "returns actual durations if fabricated ones are omitted for some blocks" do
688696
@ex.use { true }
689-
@ex.try { sleep 0.1; true }
690-
@ex.fabricate_durations_for_testing_purposes( "control" => 0.5 )
691-
697+
@ex.try do
698+
start_time = Time.now
699+
while Time.now - start_time < 0.1
700+
# Perform some CPU-intensive work
701+
(1..1000).each { |i| i * i }
702+
end
703+
true
704+
end
705+
@ex.fabricate_durations_for_testing_purposes({ "control" => { "duration" => 0.5, "cpu_time" => 0.4 }})
692706
@ex.run
693707

694708
cont = @ex.published_result.control
695709
cand = @ex.published_result.candidates.first
710+
711+
# Fabricated durations
696712
assert_in_delta 0.5, cont.duration, 0.01
713+
assert_in_delta 0.4, cont.cpu_time, 0.01
714+
715+
# Measured durations
697716
assert_in_delta 0.1, cand.duration, 0.01
717+
assert_in_delta 0.1, cand.cpu_time, 0.01
698718
end
699719
end
700720
end

test/scientist/observation_test.rb

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,18 @@
66

77
it "observes and records the execution of a block" do
88
ob = Scientist::Observation.new("test", @experiment) do
9-
sleep 0.1
9+
start_time = Time.now
10+
while Time.now - start_time < 0.1
11+
# Perform some CPU-intensive work
12+
(1..1000).each { |i| i * i }
13+
end
1014
"ret"
1115
end
1216

1317
assert_equal "ret", ob.value
1418
refute ob.raised?
1519
assert_in_delta 0.1, ob.duration, 0.01
20+
assert_in_delta 0.1, ob.cpu_time, 0.01
1621
end
1722

1823
it "stashes exceptions" do

0 commit comments

Comments
 (0)