diff --git a/base/exports.jl b/base/exports.jl index ba454936cb7f3f..3c7baa40cb5fcf 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 b550d1f29e2ab6..4feed03dd3722f 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 @@ -194,6 +197,9 @@ See also [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and 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); @@ -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() @@ -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). @@ -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() @@ -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 diff --git a/doc/src/base/base.md b/doc/src/base/base.md index 1e419460bef533..d03542691782a1 100644 --- a/doc/src/base/base.md +++ b/doc/src/base/base.md @@ -320,6 +320,7 @@ Base.Libc.getpid Base.Libc.time() Base.time_ns Base.@time +Base.@showtime Base.@timev Base.@timed Base.@elapsed diff --git a/test/misc.jl b/test/misc.jl index 94c35c43ffaec5..1ef54534085914 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -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