Skip to content

Commit 275a8c0

Browse files
vchuravyvchuravy
committed
Measure both real-time and cpu-time
Renames `times` and `time` to `realtime` and `realtimes` throughout and adds `cputime` and `cputimes`. Real-time is the actual monotonic run time of the code and cpu-time is the time spend in userspace running on processor. ``` julia> @Btime sin(1) 7.572 ns [100.00% CPU, 0.00% GC] (0 allocations: 0 bytes) 0.8414709848078965 julia> @Btime sleep(1) 1.002 s [0.01% CPU, 0.00% GC] (5 allocations: 192 bytes) ```
1 parent 3e41724 commit 275a8c0

File tree

9 files changed

+152
-104
lines changed

9 files changed

+152
-104
lines changed

‎src/BenchmarkTools.jl

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -80,4 +80,14 @@ export tune!,
8080

8181
include("serialization.jl")
8282

83+
#################
84+
# Deprecations #
85+
#################
86+
import Base: time
87+
@deprecate time(t::Trial) realtime(t)
88+
@deprecate time(t::TrialJudgement) realtime(t)
89+
@deprecate time(t::TrialEstimate) realtime(t)
90+
@deprecate time(t::TrialRatio) realtime(t)
91+
@deprecate time(group::BenchmarkGroup) realtime(group)
92+
8393
end # module BenchmarkTools

‎src/execution.jl

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -314,21 +314,24 @@ function generate_benchmark_definition(eval_module, out_vars, setup_vars, core,
314314
$(setup)
315315
__evals = __params.evals
316316
__gc_start = Base.gc_num()
317-
__start_time = time_ns()
317+
__start_realtime = $BenchmarkTools.Timers.realtime()
318+
__start_cputime = $BenchmarkTools.Timers.cputime()
318319
__return_val = $(invocation)
319320
for __iter in 2:__evals
320321
$(invocation)
321322
end
322-
__sample_time = time_ns() - __start_time
323+
__sample_realtime = $BenchmarkTools.Timers.realtime() - __start_realtime
324+
__sample_cputime = $BenchmarkTools.Timers.cputime() - __start_cputime
323325
__gcdiff = Base.GC_Diff(Base.gc_num(), __gc_start)
324326
$(teardown)
325-
__time = max((__sample_time / __evals) - __params.overhead, 0.001)
327+
__realtime = max((__sample_realtime / __evals) - __params.overhead, 0.001)
328+
__cputime = max((__sample_cputime / __evals) - __params.overhead, 0.001)
326329
__gctime = max((__gcdiff.total_time / __evals) - __params.overhead, 0.0)
327330
__memory = Int(fld(__gcdiff.allocd, __evals))
328331
__allocs = Int(fld(__gcdiff.malloc + __gcdiff.realloc +
329332
__gcdiff.poolalloc + __gcdiff.bigalloc,
330333
__evals))
331-
return __time, __gctime, __memory, __allocs, __return_val
334+
return __realtime, __cputime, __gctime, __memory, __allocs, __return_val
332335
end
333336
function $BenchmarkTools.sample(b::$BenchmarkTools.Benchmark{$(id)},
334337
p::$BenchmarkTools.Parameters = b.params)
@@ -379,7 +382,7 @@ is the *minimum* elapsed time measured during the benchmark.
379382
macro belapsed(args...)
380383
b = Expr(:macrocall, Symbol("@benchmark"), map(esc, args)...)
381384
return esc(quote
382-
$BenchmarkTools.time($BenchmarkTools.minimum($BenchmarkTools.@benchmark $(args...)))/1e9
385+
$BenchmarkTools.realtime($BenchmarkTools.minimum($BenchmarkTools.@benchmark $(args...)))/1e9
383386
end)
384387
end
385388

@@ -409,7 +412,9 @@ macro btime(args...)
409412
$trialmin = $BenchmarkTools.minimum($trial)
410413
$trialallocs = $BenchmarkTools.allocs($trialmin)
411414
println(" ",
412-
$BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
415+
$BenchmarkTools.prettytime($BenchmarkTools.realtime($trialmin)), " [",
416+
$BenchmarkTools.prettypercent($BenchmarkTools.cpuratio($trialmin)), " CPU, ",
417+
$BenchmarkTools.prettypercent($BenchmarkTools.gcratio($trialmin)), " GC]",
413418
" (", $trialallocs , " allocation",
414419
$trialallocs == 1 ? "" : "s", ": ",
415420
$BenchmarkTools.prettymemory($BenchmarkTools.memory($trialmin)), ")")

‎src/groups.jl

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -81,7 +81,8 @@ Base.median(group::BenchmarkGroup) = mapvals(median, group)
8181
Base.min(groups::BenchmarkGroup...) = mapvals(min, groups...)
8282
Base.max(groups::BenchmarkGroup...) = mapvals(max, groups...)
8383

84-
Base.time(group::BenchmarkGroup) = mapvals(time, group)
84+
realtime(group::BenchmarkGroup) = mapvals(realtime, group)
85+
cputime(group::BenchmarkGroup) = mapvals(cputime, group)
8586
gctime(group::BenchmarkGroup) = mapvals(gctime, group)
8687
memory(group::BenchmarkGroup) = mapvals(memory, group)
8788
allocs(group::BenchmarkGroup) = mapvals(allocs, group)

‎src/parameters.jl

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -75,12 +75,14 @@ end
7575
@noinline nullfunc() = nothing
7676

7777
@noinline function overhead_sample(evals)
78-
start_time = time_ns()
78+
start_realtime = Timers.realtime()
79+
start_cputime = Timers.cputime()
7980
for _ in 1:evals
8081
nullfunc()
8182
end
82-
sample_time = time_ns() - start_time
83-
return (sample_time / evals)
83+
sample_realtime = Timers.realtime() - start_realtime
84+
sample_cputime = Timers.cputtime() - start_cputime
85+
return (sample_realtime / evals, sample_cputime / evals)
8486
end
8587

8688
function estimate_overhead()

‎src/serialization.jl

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
if VERSION >= v"0.7.0-DEV.2437"
2-
using Base.Meta.parse
2+
using Base.Meta: parse
33
end
44

55
const VERSIONS = Dict("Julia" => string(VERSION),

‎src/trials.jl

Lines changed: 74 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -4,53 +4,59 @@
44

55
mutable struct Trial
66
params::Parameters
7-
times::Vector{Float64}
7+
realtimes::Vector{Float64}
8+
cputimes::Vector{Float64}
89
gctimes::Vector{Float64}
910
memory::Int
1011
allocs::Int
1112
end
1213

13-
Trial(params::Parameters) = Trial(params, Float64[], Float64[], typemax(Int), typemax(Int))
14+
Trial(params::Parameters) = Trial(params, Float64[], Float64[], Float64[], typemax(Int), typemax(Int))
1415

1516
@compat function Base.:(==)(a::Trial, b::Trial)
1617
return a.params == b.params &&
17-
a.times == b.times &&
18+
a.realtimes == b.realtimes &&
19+
a.cputimes == b.cputimes &&
1820
a.gctimes == b.gctimes &&
1921
a.memory == b.memory &&
2022
a.allocs == b.allocs
2123
end
2224

23-
Base.copy(t::Trial) = Trial(copy(t.params), copy(t.times), copy(t.gctimes), t.memory, t.allocs)
25+
Base.copy(t::Trial) = Trial(copy(t.params), copy(t.realtimes), copy(t.cputimes), copy(t.gctimes), t.memory, t.allocs)
2426

25-
function Base.push!(t::Trial, time, gctime, memory, allocs)
26-
push!(t.times, time)
27+
function Base.push!(t::Trial, realtime, cputime, gctime, memory, allocs)
28+
push!(t.realtimes, realtime)
29+
push!(t.cputimes, cputime)
2730
push!(t.gctimes, gctime)
2831
memory < t.memory && (t.memory = memory)
2932
allocs < t.allocs && (t.allocs = allocs)
3033
return t
3134
end
3235

3336
function Base.deleteat!(t::Trial, i)
34-
deleteat!(t.times, i)
37+
deleteat!(t.realtimes, i)
38+
deleteat!(t.cputimes, i)
3539
deleteat!(t.gctimes, i)
3640
return t
3741
end
3842

39-
Base.length(t::Trial) = length(t.times)
40-
Base.getindex(t::Trial, i::Number) = push!(Trial(t.params), t.times[i], t.gctimes[i], t.memory, t.allocs)
41-
Base.getindex(t::Trial, i) = Trial(t.params, t.times[i], t.gctimes[i], t.memory, t.allocs)
43+
Base.length(t::Trial) = length(t.realtimes)
44+
Base.getindex(t::Trial, i::Number) = push!(Trial(t.params), t.realtimes[i], t.cputimes[i], t.gctimes[i], t.memory, t.allocs)
45+
Base.getindex(t::Trial, i) = Trial(t.params, t.realtimes[i], t.cputimes[i], t.gctimes[i], t.memory, t.allocs)
4246
Base.endof(t::Trial) = length(t)
4347

4448
function Base.sort!(t::Trial)
45-
inds = sortperm(t.times)
46-
t.times = t.times[inds]
49+
inds = sortperm(t.realtimes)
50+
t.realtimes = t.realtimes[inds]
51+
t.cputimes = t.cputimes[inds]
4752
t.gctimes = t.gctimes[inds]
4853
return t
4954
end
5055

5156
Base.sort(t::Trial) = sort!(copy(t))
5257

53-
Base.time(t::Trial) = time(minimum(t))
58+
realtime(t::Trial) = realtime(minimum(t))
59+
cputime(t::Trial) = cputime(minimum(t))
5460
gctime(t::Trial) = gctime(minimum(t))
5561
memory(t::Trial) = t.memory
5662
allocs(t::Trial) = t.allocs
@@ -66,7 +72,7 @@ function skewcutoff(values)
6672
return length(current_values) + 1
6773
end
6874

69-
skewcutoff(t::Trial) = skewcutoff(t.times)
75+
skewcutoff(t::Trial) = skewcutoff(t.realtimes)
7076

7177
function rmskew!(t::Trial)
7278
sort!(t)
@@ -88,19 +94,21 @@ trim(t::Trial, percentage = 0.1) = t[1:max(1, floor(Int, length(t) - (length(t)
8894

8995
mutable struct TrialEstimate
9096
params::Parameters
91-
time::Float64
97+
realtime::Float64
98+
cputime::Float64
9299
gctime::Float64
93100
memory::Int
94101
allocs::Int
95102
end
96103

97-
function TrialEstimate(trial::Trial, t, gct)
98-
return TrialEstimate(params(trial), t, gct, memory(trial), allocs(trial))
104+
function TrialEstimate(trial::Trial, realtime, cputime, gctime)
105+
return TrialEstimate(params(trial), realtime, cputime, gctime, memory(trial), allocs(trial))
99106
end
100107

101108
@compat function Base.:(==)(a::TrialEstimate, b::TrialEstimate)
102109
return a.params == b.params &&
103-
a.time == b.time &&
110+
a.realtime == b.realtime &&
111+
a.cputime == b.cputime &&
104112
a.gctime == b.gctime &&
105113
a.memory == b.memory &&
106114
a.allocs == b.allocs
@@ -109,21 +117,22 @@ end
109117
Base.copy(t::TrialEstimate) = TrialEstimate(copy(t.params), t.time, t.gctime, t.memory, t.allocs)
110118

111119
function Base.minimum(trial::Trial)
112-
i = indmin(trial.times)
113-
return TrialEstimate(trial, trial.times[i], trial.gctimes[i])
120+
i = indmin(trial.realtimes)
121+
return TrialEstimate(trial, trial.realtimes[i], trial.cputimes[i], trial.gctimes[i])
114122
end
115123

116124
function Base.maximum(trial::Trial)
117-
i = indmax(trial.times)
118-
return TrialEstimate(trial, trial.times[i], trial.gctimes[i])
125+
i = indmax(trial.realtimes)
126+
return TrialEstimate(trial, trial.realtimes[i], trial.cputimes[i], trial.gctimes[i])
119127
end
120128

121-
Base.median(trial::Trial) = TrialEstimate(trial, median(trial.times), median(trial.gctimes))
122-
Base.mean(trial::Trial) = TrialEstimate(trial, mean(trial.times), mean(trial.gctimes))
129+
Base.median(trial::Trial) = TrialEstimate(trial, median(trial.realtimes), median(trial.cputimes), median(trial.gctimes))
130+
Base.mean(trial::Trial) = TrialEstimate(trial, mean(trial.realtimes), mean(trial.cputimes), mean(trial.gctimes))
123131

124-
Base.isless(a::TrialEstimate, b::TrialEstimate) = isless(time(a), time(b))
132+
Base.isless(a::TrialEstimate, b::TrialEstimate) = isless(realtime(a), realtime(b))
125133

126-
Base.time(t::TrialEstimate) = t.time
134+
realtime(t::TrialEstimate) = t.realtime
135+
cputime(t::TrialEstimate) = t.cputime
127136
gctime(t::TrialEstimate) = t.gctime
128137
memory(t::TrialEstimate) = t.memory
129138
allocs(t::TrialEstimate) = t.allocs
@@ -135,23 +144,26 @@ params(t::TrialEstimate) = t.params
135144

136145
mutable struct TrialRatio
137146
params::Parameters
138-
time::Float64
147+
realtime::Float64
148+
cputime::Float64
139149
gctime::Float64
140150
memory::Float64
141151
allocs::Float64
142152
end
143153

144154
@compat function Base.:(==)(a::TrialRatio, b::TrialRatio)
145155
return a.params == b.params &&
146-
a.time == b.time &&
156+
a.realtime == b.realtime &&
157+
a.cputime == b.cputime &&
147158
a.gctime == b.gctime &&
148159
a.memory == b.memory &&
149160
a.allocs == b.allocs
150161
end
151162

152-
Base.copy(t::TrialRatio) = TrialRatio(copy(t.params), t.time, t.gctime, t.memory, t.allocs)
163+
Base.copy(t::TrialRatio) = TrialRatio(copy(t.params), t.realtime, t.cputime, t.gctime, t.memory, t.allocs)
153164

154-
Base.time(t::TrialRatio) = t.time
165+
realtime(t::TrialRatio) = t.realtime
166+
cputime(t::TrialRatio) = t.cputime
155167
gctime(t::TrialRatio) = t.gctime
156168
memory(t::TrialRatio) = t.memory
157169
allocs(t::TrialRatio) = t.allocs
@@ -168,37 +180,42 @@ function ratio(a::TrialEstimate, b::TrialEstimate)
168180
ttol = max(params(a).time_tolerance, params(b).time_tolerance)
169181
mtol = max(params(a).memory_tolerance, params(b).memory_tolerance)
170182
p = Parameters(params(a); time_tolerance = ttol, memory_tolerance = mtol)
171-
return TrialRatio(p, ratio(time(a), time(b)), ratio(gctime(a), gctime(b)),
172-
ratio(memory(a), memory(b)), ratio(allocs(a), allocs(b)))
183+
return TrialRatio(p, ratio(realtime(a), realtime(b)), ratio(cputime(a), cputime(b)),
184+
ratio(gctime(a), gctime(b)), ratio(memory(a), memory(b)),
185+
ratio(allocs(a), allocs(b)))
173186
end
174187

175-
gcratio(t::TrialEstimate) = ratio(gctime(t), time(t))
188+
gcratio(t::TrialEstimate) = ratio(gctime(t), realtime(t))
189+
cpuratio(t::TrialEstimate) = ratio(cputime(t), realtime(t))
176190

177191
##################
178192
# TrialJudgement #
179193
##################
180194

181195
struct TrialJudgement
182196
ratio::TrialRatio
183-
time::Symbol
197+
realtime::Symbol
198+
cputime::Symbol
184199
memory::Symbol
185200
end
186201

187202
function TrialJudgement(r::TrialRatio)
188203
ttol = params(r).time_tolerance
189204
mtol = params(r).memory_tolerance
190-
return TrialJudgement(r, judge(time(r), ttol), judge(memory(r), mtol))
205+
return TrialJudgement(r, judge(realtime(r), ttol), judge(cputime(r), ttol), judge(memory(r), mtol))
191206
end
192207

193208
@compat function Base.:(==)(a::TrialJudgement, b::TrialJudgement)
194209
return a.ratio == b.ratio &&
195-
a.time == b.time &&
210+
a.realtime == b.realtime &&
211+
a.cputime == b.cputime &&
196212
a.memory == b.memory
197213
end
198214

199-
Base.copy(t::TrialJudgement) = TrialJudgement(copy(t.params), t.time, t.memory)
215+
Base.copy(t::TrialJudgement) = TrialJudgement(copy(t.params), t.realtime, t.cputime, t.memory)
200216

201-
Base.time(t::TrialJudgement) = t.time
217+
realtime(t::TrialJudgement) = t.realtime
218+
cputime(t::TrialJudgement) = t.cputime
202219
memory(t::TrialJudgement) = t.memory
203220
ratio(t::TrialJudgement) = t.ratio
204221
params(t::TrialJudgement) = params(ratio(t))
@@ -221,9 +238,9 @@ function judge(ratio::Real, tolerance::Float64)
221238
end
222239
end
223240

224-
isimprovement(t::TrialJudgement) = time(t) == :improvement || memory(t) == :improvement
225-
isregression(t::TrialJudgement) = time(t) == :regression || memory(t) == :regression
226-
isinvariant(t::TrialJudgement) = time(t) == :invariant && memory(t) == :invariant
241+
isimprovement(t::TrialJudgement) = realtime(t) == :improvement || cputime(t) == :improvement || memory(t) == :improvement
242+
isregression(t::TrialJudgement) = realtime(t) == :regression || cputime(t) == :regression || memory(t) == :regression
243+
isinvariant(t::TrialJudgement) = realtime(t) == :invariant && cputime(t) == :invariant && memory(t) == :invariant
227244

228245
###################
229246
# Pretty Printing #
@@ -262,10 +279,10 @@ function prettymemory(b)
262279
return string(@sprintf("%.2f", value), " ", units)
263280
end
264281

265-
Base.show(io::IO, t::Trial) = print(io, "Trial(", prettytime(time(t)), ")")
266-
Base.show(io::IO, t::TrialEstimate) = print(io, "TrialEstimate(", prettytime(time(t)), ")")
267-
Base.show(io::IO, t::TrialRatio) = print(io, "TrialRatio(", prettypercent(time(t)), ")")
268-
Base.show(io::IO, t::TrialJudgement) = print(io, "TrialJudgement(", prettydiff(time(ratio(t))), " => ", time(t), ")")
282+
Base.show(io::IO, t::Trial) = print(io, "Trial(", prettytime(realtime(t)), ")")
283+
Base.show(io::IO, t::TrialEstimate) = print(io, "TrialEstimate(", prettytime(realtime(t)), ")")
284+
Base.show(io::IO, t::TrialRatio) = print(io, "TrialRatio(", prettypercent(realtime(t)), ")")
285+
Base.show(io::IO, t::TrialJudgement) = print(io, "TrialJudgement(", prettydiff(realtime(ratio(t))), " => ", realtime(t), ")")
269286

270287
@compat function Base.show(io::IO, ::MIME"text/plain", t::Trial)
271288
if length(t) > 0
@@ -275,10 +292,10 @@ Base.show(io::IO, t::TrialJudgement) = print(io, "TrialJudgement(", prettydiff(t
275292
avg = mean(t)
276293
memorystr = string(prettymemory(memory(min)))
277294
allocsstr = string(allocs(min))
278-
minstr = string(prettytime(time(min)), " (", prettypercent(gcratio(min)), " GC)")
279-
maxstr = string(prettytime(time(med)), " (", prettypercent(gcratio(med)), " GC)")
280-
medstr = string(prettytime(time(avg)), " (", prettypercent(gcratio(avg)), " GC)")
281-
meanstr = string(prettytime(time(max)), " (", prettypercent(gcratio(max)), " GC)")
295+
minstr = string(prettytime(realtime(min)), " (", prettypercent(cpuratio(min)) ," CPU, ", prettypercent(gcratio(min)), " GC)")
296+
maxstr = string(prettytime(realtime(med)), " (", prettypercent(cpuratio(med)) ," CPU, ", prettypercent(gcratio(med)), " GC)")
297+
medstr = string(prettytime(realtime(avg)), " (", prettypercent(cpuratio(avg)) ," CPU, ", prettypercent(gcratio(avg)), " GC)")
298+
meanstr = string(prettytime(realtime(max)), " (", prettypercent(cpuratio(max)) ," CPU, ", prettypercent(gcratio(max)), " GC)")
282299
else
283300
memorystr = "N/A"
284301
allocsstr = "N/A"
@@ -302,22 +319,25 @@ end
302319

303320
@compat function Base.show(io::IO, ::MIME"text/plain", t::TrialEstimate)
304321
println(io, "BenchmarkTools.TrialEstimate: ")
305-
println(io, " time: ", prettytime(time(t)))
306-
println(io, " gctime: ", prettytime(gctime(t)), " (", prettypercent(gctime(t) / time(t)),")")
322+
println(io, " realtime: ", prettytime(realtime(t)))
323+
println(io, " cputime: ", prettytime(cputime(t)), " (", prettypercent(cputime(t) / realtime(t)),")")
324+
println(io, " gctime: ", prettytime(gctime(t)), " (", prettypercent(gctime(t) / realtime(t)),")")
307325
println(io, " memory: ", prettymemory(memory(t)))
308326
print(io, " allocs: ", allocs(t))
309327
end
310328

311329
@compat function Base.show(io::IO, ::MIME"text/plain", t::TrialRatio)
312330
println(io, "BenchmarkTools.TrialRatio: ")
313-
println(io, " time: ", time(t))
331+
println(io, " realtime: ", realtime(t))
332+
println(io, " cputime: ", cputime(t))
314333
println(io, " gctime: ", gctime(t))
315334
println(io, " memory: ", memory(t))
316335
print(io, " allocs: ", allocs(t))
317336
end
318337

319338
@compat function Base.show(io::IO, ::MIME"text/plain", t::TrialJudgement)
320339
println(io, "BenchmarkTools.TrialJudgement: ")
321-
println(io, " time: ", prettydiff(time(ratio(t))), " => ", time(t), " (", prettypercent(params(t).time_tolerance), " tolerance)")
322-
print(io, " memory: ", prettydiff(memory(ratio(t))), " => ", memory(t), " (", prettypercent(params(t).memory_tolerance), " tolerance)")
340+
println(io, " realtime: ", prettydiff(realtime(ratio(t))), " => ", realtime(t), " (", prettypercent(params(t).time_tolerance), " tolerance)")
341+
println(io, " cputime: ", prettydiff(cputime(ratio(t))), " => ", cputime(t), " (", prettypercent(params(t).time_tolerance), " tolerance)")
342+
print(io, " memory: ", prettydiff(memory(ratio(t))), " => ", memory(t), " (", prettypercent(params(t).memory_tolerance), " tolerance)")
323343
end

0 commit comments

Comments
 (0)