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 Sep 30, 2021
1 parent 45bf516 commit e885257
Show file tree
Hide file tree
Showing 2 changed files with 51 additions and 5 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
55 changes: 50 additions & 5 deletions base/timing.jl
Original file line number Diff line number Diff line change
Expand Up @@ -175,18 +175,21 @@ 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
Expand All @@ -209,9 +212,20 @@ 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.003785 seconds (4 allocations: 128 bytes)
```
"""
macro time(ex)
macro time(ex...)
if length(ex) == 2 && ex[1] isa String
msg, ex = ex
elseif length(ex) == 1
msg, ex = nothing, ex[1]
else
error("Incorrect format used with @time. Valid forms are `@time expr` or `@time \"msg\" expr`")
end
quote
@compile
local stats = gc_num()
Expand All @@ -222,18 +236,41 @@ macro time(ex)
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
)
local diff = GC_Diff(gc_num(), stats)
isnothing($msg) || print($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.
See also [`@time`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and
[`@allocated`](@ref).
Expand All @@ -258,7 +295,14 @@ bytes allocated: 896
pool allocs: 1
```
"""
macro timev(ex)
macro timev(ex...)
if length(ex) == 2 && ex[1] isa String
msg, ex = ex
elseif length(ex) == 1
msg, ex = nothing, ex[1]
else
error("Incorrect format used with @timev. Valid forms are `@timev expr` or `@timev \"msg\" expr`")
end
quote
@compile
local stats = gc_num()
Expand All @@ -269,6 +313,7 @@ macro timev(ex)
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
)
local diff = GC_Diff(gc_num(), stats)
isnothing($msg) || print($msg, " ->")
timev_print(elapsedtime, diff, compile_elapsedtime)
val
end
Expand Down

0 comments on commit e885257

Please sign in to comment.