From e885257684a56daa6bc8d202f69b8f60d2313a1e Mon Sep 17 00:00:00 2001 From: Ian Date: Wed, 29 Sep 2021 23:55:13 -0400 Subject: [PATCH] add optional description to `@time` and new `@showtime` macro --- base/exports.jl | 1 + base/timing.jl | 55 ++++++++++++++++++++++++++++++++++++++++++++----- 2 files changed, 51 insertions(+), 5 deletions(-) diff --git a/base/exports.jl b/base/exports.jl index ba454936cb7f3..3c7baa40cb5fc 100644 --- a/base/exports.jl +++ b/base/exports.jl @@ -992,6 +992,7 @@ export # profiling @time, + @showtime, @timed, @timev, @elapsed, diff --git a/base/timing.jl b/base/timing.jl index 157fe288b9708..ca817e375fba8 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -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 @@ -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() @@ -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). @@ -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() @@ -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