From 27078f6e14e0b81a8866663ee71ae3deba718132 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Mon, 25 Oct 2021 15:29:09 -0400 Subject: [PATCH] Add optional description to `@time` and new `@showtime` macro (#42431) --- NEWS.md | 3 +++ base/exports.jl | 1 + base/timing.jl | 61 +++++++++++++++++++++++++++++++++++++++++--- doc/src/base/base.md | 1 + test/misc.jl | 29 +++++++++++++++++++++ 5 files changed, 92 insertions(+), 3 deletions(-) diff --git a/NEWS.md b/NEWS.md index dcb438d5ba8938..9fca99a785f3a3 100644 --- a/NEWS.md +++ b/NEWS.md @@ -22,6 +22,9 @@ Language changes * Newly created Task objects (`@spawn`, `@async`, etc.) now adopt the world-age for methods from their parent Task upon creation, instead of using the global latest world at start. This is done to enable inference to eventually optimize these calls. Places that wish for the old behavior may use `Base.invokelatest`. ([#41449]) +* `@time` and `@timev` now take an optional description to allow annotating the source of time reports. + i.e. `@time "Evaluating foo" foo()` ([#42431]) +* New `@showtime` macro to show both the line being evaluated and the `@time` report ([#42431]) Compiler/Runtime improvements ----------------------------- 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..57b3ee3bef81b6 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,46 @@ 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. + +!!! compat "Julia 1.8" + This macro was added in Julia 1.8. + +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 +308,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 +323,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..7543e0375fd281 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() +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