Skip to content

Commit

Permalink
add optional description to @time and new @showtime macro
Browse files Browse the repository at this point in the history
  • Loading branch information
IanButterworth committed Oct 23, 2021
1 parent 5f11f5b commit f686b09
Show file tree
Hide file tree
Showing 4 changed files with 86 additions and 3 deletions.
1 change: 1 addition & 0 deletions base/exports.jl
Original file line number Diff line number Diff line change
Expand Up @@ -992,6 +992,7 @@ export

# profiling
@time,
@showtime,
@timed,
@timev,
@elapsed,
Expand Down
58 changes: 55 additions & 3 deletions base/timing.jl
Original file line number Diff line number Diff line change
Expand Up @@ -175,25 +175,31 @@ macro __tryfinally(ex, fin)
end

"""
@time
@time expr
@time "description" expr
A macro to execute an expression, printing the time it took to execute, the number of
allocations, and the total number of bytes its execution caused to be allocated, before
returning the value of the expression. Any time spent garbage collecting (gc) or
compiling is shown as a percentage.
Optionally provide a description string to print before the time report.
In some cases the system will look inside the `@time` expression and compile some of the
called code before execution of the top-level expression begins. When that happens, some
compilation time will not be counted. To include this time you can run `@time @eval ...`.
See also [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and
See also [`@showtime`](@ref), [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and
[`@allocated`](@ref).
!!! note
For more serious benchmarking, consider the `@btime` macro from the BenchmarkTools.jl
package which among other things evaluates the function multiple times in order to
reduce noise.
!!! compat "Julia 1.8"
The option to add a description was introduced in Julia 1.8.
```julia-repl
julia> x = rand(10,10);
Expand All @@ -209,9 +215,24 @@ julia> @time begin
end
0.301395 seconds (8 allocations: 336 bytes)
2
julia> @time "A one second sleep" sleep(1)
A one second sleep -> 1.005750 seconds (5 allocations: 144 bytes)
julia> for loop in 1:3
@time loop sleep(1)
end
1 -> 1.006760 seconds (5 allocations: 144 bytes)
2 -> 1.001263 seconds (5 allocations: 144 bytes)
3 -> 1.003676 seconds (5 allocations: 144 bytes)
```
"""
macro time(ex)
quote
@time nothing $(esc(ex))
end
end
macro time(msg, ex)
quote
Experimental.@force_compile
local stats = gc_num()
Expand All @@ -222,18 +243,43 @@ macro time(ex)
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
)
local diff = GC_Diff(gc_num(), stats)
isnothing($(esc(msg))) || print($(esc(msg)), " ->")
time_print(elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), compile_elapsedtime, true)
val
end
end

"""
@timev
@showtime expr
Like `@time` but also prints the expression being evaluated for reference.
See also [`@time`](@ref).
```julia-repl
julia> @showtime sleep(1)
sleep(1) -> 1.002164 seconds (4 allocations: 128 bytes)
```
"""
macro showtime(ex)
quote
@time $(sprint(show_unquoted,ex)) $(esc(ex))
end
end

"""
@timev expr
@timev "description" expr
This is a verbose version of the `@time` macro. It first prints the same information as
`@time`, then any non-zero memory allocation counters, and then returns the value of the
expression.
Optionally provide a description string to print before the time report.
!!! compat "Julia 1.8"
The option to add a description was introduced in Julia 1.8.
See also [`@time`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and
[`@allocated`](@ref).
Expand All @@ -259,6 +305,11 @@ pool allocs: 1
```
"""
macro timev(ex)
quote
@timev nothing $(esc(ex))
end
end
macro timev(msg, ex)
quote
Experimental.@force_compile
local stats = gc_num()
Expand All @@ -269,6 +320,7 @@ macro timev(ex)
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
)
local diff = GC_Diff(gc_num(), stats)
isnothing($(esc(msg))) || print($(esc(msg)), " ->")
timev_print(elapsedtime, diff, compile_elapsedtime)
val
end
Expand Down
1 change: 1 addition & 0 deletions doc/src/base/base.md
Original file line number Diff line number Diff line change
Expand Up @@ -320,6 +320,7 @@ Base.Libc.getpid
Base.Libc.time()
Base.time_ns
Base.@time
Base.@showtime
Base.@timev
Base.@timed
Base.@elapsed
Expand Down
29 changes: 29 additions & 0 deletions test/misc.jl
Original file line number Diff line number Diff line change
Expand Up @@ -242,6 +242,35 @@ v11801, t11801 = @timed sin(1)

@test names(@__MODULE__, all = true) == names_before_timing

# Accepted @time argument formats
@test @time true
@test @time "message" true
let msg = "message"
@test @time msg true
end
let foo() = "message"
@test @time foo() true
end

# Accepted @timev argument formats
@test @timev true
@test @timev "message" true
let msg = "message"
@test @timev msg true
end
let foo() = "message"
@test @timev foo() true
end

# @showtime
@test @showtime true
let foo() = true
@test (@showtime foo()) == false
end
let foo() = false
@test (@showtime foo()) == false
end

# PR #39133, ensure that @time evaluates in the same scope
function time_macro_scope()
try # try/throw/catch bypasses printing
Expand Down

0 comments on commit f686b09

Please sign in to comment.