Skip to content

Commit b6ae23c

Browse files
committed
Update docs and disable printing of cpu-time
`:GetProcessTimes` has a resolution of `100ns` which is much worse than the resolution of the high-precision clock.
1 parent e4c3ce8 commit b6ae23c

File tree

3 files changed

+28
-9
lines changed

3 files changed

+28
-9
lines changed

doc/manual.md

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -46,17 +46,22 @@ recording the total time `t` it takes to record `n` evaluations, and estimating
4646

4747
## The difference between real-time and cpu-time
4848
BenchmarkTools measures both real-time and cpu-time. Real-time is the time that has passed while running your program and cpu-time is the time
49-
that a processor has spend executing your program. As an example when the operating system deschedules your program, real-time is still passing,
50-
but cpu-time is paused, this is also the case when your program spends time in the kernel or is blocked waiting. As an example take a program that
49+
that a processor has spend executing your program. Real-time is often also referred to as wall-time. As an example take a program that
5150
is doing `sleep(1)`.
5251

5352
```julia
5453
julia> @btime sleep(1)
5554
1.001 s [0.01% CPU, 0.00% GC] (5 allocations: 192 bytes)
5655
```
5756

58-
As we can see, when we call sleep our program is not using CPU cycles and thus cpu-time is `0.01%` of our actual runtime. Do to sligh differences
59-
in accounting cpu-time can sometimes exceed `100%`.
57+
As we can see, when we call sleep our program is not using CPU cycles and thus cpu-time is `0.01%` of our actual runtime.
58+
Sometimes cpu-time can exceed `100%`, this is either due to slight differences in accounting or because your process is
59+
using multiple cpus.
60+
61+
### Windows
62+
Cpu-time measurments on Windows have a low resolution (in comparision to real-time) and are as such less useful. To avoid confusion
63+
printing of cpu-time is disabled by default. If you are benchmarking code that runs in the `ms` range you can set the environment variable
64+
`BT_FORCE_CPUTIME` to enable printing of cpu-time results (Remeber to evict your cached version of BenchmarkTools).
6065

6166
# Benchmarking basics
6267

src/timers/timers.jl

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33
module Timers
44
import Compat
55

6+
const ACCURATE_CPUTIME = Compat.Sys.iswindows() ? haskey(ENV, "BT_FORCE_CPUTIME") : true
7+
68
"""
79
realtime()
810

src/trials.jl

Lines changed: 17 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -188,7 +188,7 @@ function ratio(a::TrialEstimate, b::TrialEstimate)
188188
end
189189

190190
gcratio(t::TrialEstimate) = ratio(gctime(t), realtime(t))
191-
cpuratio(t::TrialEstimate) = ratio(cputime(t), realtime(t))
191+
cpuratio(t::TrialEstimate) = Timers.ACCURATE_CPUTIME ? ratio(cputime(t), realtime(t)) : NaN
192192

193193
##################
194194
# TrialJudgement #
@@ -322,16 +322,24 @@ end
322322
@compat function Base.show(io::IO, ::MIME"text/plain", t::TrialEstimate)
323323
println(io, "BenchmarkTools.TrialEstimate: ")
324324
println(io, " realtime: ", prettytime(realtime(t)))
325-
println(io, " cputime: ", prettytime(cputime(t)), " (", prettypercent(cputime(t) / realtime(t)),")")
326-
println(io, " gctime: ", prettytime(gctime(t)), " (", prettypercent(gctime(t) / realtime(t)),")")
325+
if Timers.ACCURATE_CPUTIME
326+
println(io, " cputime: ", prettytime(cputime(t)), " (", prettypercent(cpuratio(t)),")")
327+
else
328+
println(io, " cputime: ", "NA on Windows, see docs")
329+
end
330+
println(io, " gctime: ", prettytime(gctime(t)), " (", prettypercent(gcratio(t)),")")
327331
println(io, " memory: ", prettymemory(memory(t)))
328332
print(io, " allocs: ", allocs(t))
329333
end
330334

331335
@compat function Base.show(io::IO, ::MIME"text/plain", t::TrialRatio)
332336
println(io, "BenchmarkTools.TrialRatio: ")
333337
println(io, " realtime: ", realtime(t))
334-
println(io, " cputime: ", cputime(t))
338+
if Timers.ACCURATE_CPUTIME
339+
println(io, " cputime: ", cputime(t))
340+
else
341+
println(io, " cputime: ", "NA on Windows, see docs")
342+
end
335343
println(io, " gctime: ", gctime(t))
336344
println(io, " memory: ", memory(t))
337345
print(io, " allocs: ", allocs(t))
@@ -340,6 +348,10 @@ end
340348
@compat function Base.show(io::IO, ::MIME"text/plain", t::TrialJudgement)
341349
println(io, "BenchmarkTools.TrialJudgement: ")
342350
println(io, " realtime: ", prettydiff(realtime(ratio(t))), " => ", realtime(t), " (", prettypercent(params(t).time_tolerance), " tolerance)")
343-
println(io, " cputime: ", prettydiff(cputime(ratio(t))), " => ", cputime(t), " (", prettypercent(params(t).time_tolerance), " tolerance)")
351+
if Timers.ACCURATE_CPUTIME
352+
println(io, " cputime: ", prettydiff(cputime(ratio(t))), " => ", cputime(t), " (", prettypercent(params(t).time_tolerance), " tolerance)")
353+
else
354+
println(io, " cputime: ", "NA on Windows, see docs")
355+
end
344356
print(io, " memory: ", prettydiff(memory(ratio(t))), " => ", memory(t), " (", prettypercent(params(t).memory_tolerance), " tolerance)")
345357
end

0 commit comments

Comments
 (0)