From 4b22d7ddf91573a27487739fde4eb16d0f17b221 Mon Sep 17 00:00:00 2001 From: Ian Date: Sun, 20 Sep 2020 20:42:14 -0400 Subject: [PATCH 01/11] show any compile time spent in at-time macro --- base/timing.jl | 13 +++++++++++-- src/jitlayers.cpp | 17 +++++++++++++++++ 2 files changed, 28 insertions(+), 2 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index ac19e9a2e2ba8..8a497e649c9eb 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -55,6 +55,9 @@ function gc_alloc_count(diff::GC_Diff) diff.malloc + diff.realloc + diff.poolalloc + diff.bigalloc end +# cumulative total time spent on compilation +cumulative_compile_time_ns() = ccall(:jl_cumulative_compile_time_ns, UInt64, ()) +reset_cumulative_compile_time() = ccall(:jl_reset_cumulative_compile_time, Cvoid, ()) # total time spend in garbage collection, in nanoseconds gc_time_ns() = ccall(:jl_gc_total_hrtime, UInt64, ()) @@ -102,7 +105,7 @@ function format_bytes(bytes) # also used by InteractiveUtils end end -function time_print(elapsedtime, bytes=0, gctime=0, allocs=0) +function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0) timestr = Ryu.writefixed(Float64(elapsedtime/1e9), 6) length(timestr) < 10 && print(" "^(10 - length(timestr))) print(timestr, " seconds") @@ -118,6 +121,9 @@ function time_print(elapsedtime, bytes=0, gctime=0, allocs=0) if gctime > 0 print(", ", Ryu.writefixed(Float64(100*gctime/elapsedtime), 2), "% gc time") end + if compile_time > 0 + print(", ", Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time") + end if bytes != 0 || allocs != 0 print(")") end @@ -170,12 +176,15 @@ macro time(ex) quote while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) local stats = gc_num() + local compile_elapsedtime = cumulative_compile_time_ns() local elapsedtime = time_ns() local val = $(esc(ex)) elapsedtime = time_ns() - elapsedtime + compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime local diff = GC_Diff(gc_num(), stats) + reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter time_print(elapsedtime, diff.allocd, diff.total_time, - gc_alloc_count(diff)) + gc_alloc_count(diff), compile_elapsedtime) println() val end diff --git a/src/jitlayers.cpp b/src/jitlayers.cpp index 1e49eba98f03f..fc6a13785c9d3 100644 --- a/src/jitlayers.cpp +++ b/src/jitlayers.cpp @@ -67,6 +67,19 @@ void jl_jit_globals(std::map &globals) } } +static uint64_t cumulative_compile_time = 0; +static uint64_t compiler_start_time = 0; + +extern "C" JL_DLLEXPORT +uint64_t jl_cumulative_compile_time_ns() { + return cumulative_compile_time; +} + +extern "C" JL_DLLEXPORT +void jl_reset_cumulative_compile_time() { + cumulative_compile_time = 0; +} + // this generates llvm code for the lambda info // and adds the result to the jitlayers // (and the shadow module), @@ -200,6 +213,7 @@ static jl_callptr_t _jl_compile_codeinst( jl_printf(dump_compiles_stream, "\"\n"); } } + cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); return fptr; } @@ -210,6 +224,7 @@ extern "C" JL_DLLEXPORT void jl_compile_extern_c(void *llvmmod, void *p, void *sysimg, jl_value_t *declrt, jl_value_t *sigt) { JL_LOCK(&codegen_lock); + compiler_start_time = jl_hrtime(); jl_codegen_params_t params; jl_codegen_params_t *pparams = (jl_codegen_params_t*)p; if (pparams == NULL) @@ -281,6 +296,7 @@ extern "C" jl_code_instance_t *jl_generate_fptr(jl_method_instance_t *mi JL_PROPAGATES_ROOT, size_t world) { JL_LOCK(&codegen_lock); // also disables finalizers, to prevent any unexpected recursion + compiler_start_time = jl_hrtime(); // if we don't have any decls already, try to generate it now jl_code_info_t *src = NULL; JL_GC_PUSH1(&src); @@ -329,6 +345,7 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec) return; } JL_LOCK(&codegen_lock); + compiler_start_time = jl_hrtime(); if (unspec->invoke == NULL) { jl_code_info_t *src = NULL; JL_GC_PUSH1(&src); From 7c2bd81b2d572de662f4d5fdc3ed53a41f6f0b33 Mon Sep 17 00:00:00 2001 From: Ian Date: Sun, 20 Sep 2020 20:55:39 -0400 Subject: [PATCH 02/11] update at-timev --- base/timing.jl | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index 8a497e649c9eb..a329c4eaf92a7 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -130,9 +130,9 @@ function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0) nothing end -function timev_print(elapsedtime, diff::GC_Diff) +function timev_print(elapsedtime, diff::GC_Diff, compile_time) allocs = gc_alloc_count(diff) - time_print(elapsedtime, diff.allocd, diff.total_time, allocs) + time_print(elapsedtime, diff.allocd, diff.total_time, allocs, compile_time) print("\nelapsed time (ns): $elapsedtime\n") padded_nonzero_print(diff.total_time, "gc time (ns)") padded_nonzero_print(diff.allocd, "bytes allocated") @@ -175,6 +175,7 @@ julia> @time begin macro time(ex) quote while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) + reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter local stats = gc_num() local compile_elapsedtime = cumulative_compile_time_ns() local elapsedtime = time_ns() @@ -182,7 +183,6 @@ macro time(ex) elapsedtime = time_ns() - elapsedtime compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime local diff = GC_Diff(gc_num(), stats) - reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter time_print(elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), compile_elapsedtime) println() @@ -212,11 +212,14 @@ malloc() calls: 1 macro timev(ex) quote while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) + reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter local stats = gc_num() + local compile_elapsedtime = cumulative_compile_time_ns() local elapsedtime = time_ns() local val = $(esc(ex)) elapsedtime = time_ns() - elapsedtime - timev_print(elapsedtime, GC_Diff(gc_num(), stats)) + compile_elapsedtime = cumulative_compile_time_ns() - compile_elapsedtime + timev_print(elapsedtime, GC_Diff(gc_num(), stats), compile_elapsedtime) val end end From 876e48ed8233ffdcfbb95b36f2ea32d381834f26 Mon Sep 17 00:00:00 2001 From: Ian Date: Sun, 20 Sep 2020 21:34:59 -0400 Subject: [PATCH 03/11] remove reset_cumulative_compile_time --- base/timing.jl | 3 --- src/jitlayers.cpp | 5 ----- 2 files changed, 8 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index a329c4eaf92a7..732e56b13f348 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -57,7 +57,6 @@ end # cumulative total time spent on compilation cumulative_compile_time_ns() = ccall(:jl_cumulative_compile_time_ns, UInt64, ()) -reset_cumulative_compile_time() = ccall(:jl_reset_cumulative_compile_time, Cvoid, ()) # total time spend in garbage collection, in nanoseconds gc_time_ns() = ccall(:jl_gc_total_hrtime, UInt64, ()) @@ -175,7 +174,6 @@ julia> @time begin macro time(ex) quote while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) - reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter local stats = gc_num() local compile_elapsedtime = cumulative_compile_time_ns() local elapsedtime = time_ns() @@ -212,7 +210,6 @@ malloc() calls: 1 macro timev(ex) quote while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) - reset_cumulative_compile_time() # reduce risk of overflow on cumulative counter local stats = gc_num() local compile_elapsedtime = cumulative_compile_time_ns() local elapsedtime = time_ns() diff --git a/src/jitlayers.cpp b/src/jitlayers.cpp index fc6a13785c9d3..d65a6bbfe1a2d 100644 --- a/src/jitlayers.cpp +++ b/src/jitlayers.cpp @@ -75,11 +75,6 @@ uint64_t jl_cumulative_compile_time_ns() { return cumulative_compile_time; } -extern "C" JL_DLLEXPORT -void jl_reset_cumulative_compile_time() { - cumulative_compile_time = 0; -} - // this generates llvm code for the lambda info // and adds the result to the jitlayers // (and the shadow module), From bdce083c46ef9bea0c5d8b299357b31c8e6824b0 Mon Sep 17 00:00:00 2001 From: Ian Date: Sun, 20 Sep 2020 22:15:36 -0400 Subject: [PATCH 04/11] tie timing to codegen locks --- src/jitlayers.cpp | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/src/jitlayers.cpp b/src/jitlayers.cpp index d65a6bbfe1a2d..cdc3f55d31d6d 100644 --- a/src/jitlayers.cpp +++ b/src/jitlayers.cpp @@ -68,7 +68,6 @@ void jl_jit_globals(std::map &globals) } static uint64_t cumulative_compile_time = 0; -static uint64_t compiler_start_time = 0; extern "C" JL_DLLEXPORT uint64_t jl_cumulative_compile_time_ns() { @@ -208,7 +207,6 @@ static jl_callptr_t _jl_compile_codeinst( jl_printf(dump_compiles_stream, "\"\n"); } } - cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); return fptr; } @@ -219,7 +217,7 @@ extern "C" JL_DLLEXPORT void jl_compile_extern_c(void *llvmmod, void *p, void *sysimg, jl_value_t *declrt, jl_value_t *sigt) { JL_LOCK(&codegen_lock); - compiler_start_time = jl_hrtime(); + uint64_t compiler_start_time = jl_hrtime(); jl_codegen_params_t params; jl_codegen_params_t *pparams = (jl_codegen_params_t*)p; if (pparams == NULL) @@ -238,6 +236,7 @@ void jl_compile_extern_c(void *llvmmod, void *p, void *sysimg, jl_value_t *declr if (llvmmod == NULL) jl_add_to_ee(std::unique_ptr(into)); } + cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); } @@ -261,8 +260,10 @@ void jl_extern_c(jl_value_t *declrt, jl_tupletype_t *sigt) if (!jl_is_concrete_type(declrt) || jl_is_kind(declrt)) jl_error("@ccallable: return type must be concrete and correspond to a C type"); JL_LOCK(&codegen_lock); + uint64_t compiler_start_time = jl_hrtime(); if (!jl_type_mappable_to_c(declrt)) jl_error("@ccallable: return type doesn't correspond to a C type"); + cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); // validate method signature @@ -291,7 +292,7 @@ extern "C" jl_code_instance_t *jl_generate_fptr(jl_method_instance_t *mi JL_PROPAGATES_ROOT, size_t world) { JL_LOCK(&codegen_lock); // also disables finalizers, to prevent any unexpected recursion - compiler_start_time = jl_hrtime(); + uint64_t compiler_start_time = jl_hrtime(); // if we don't have any decls already, try to generate it now jl_code_info_t *src = NULL; JL_GC_PUSH1(&src); @@ -328,6 +329,7 @@ jl_code_instance_t *jl_generate_fptr(jl_method_instance_t *mi JL_PROPAGATES_ROOT else { codeinst = NULL; } + cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); JL_GC_POP(); return codeinst; @@ -340,7 +342,7 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec) return; } JL_LOCK(&codegen_lock); - compiler_start_time = jl_hrtime(); + uint64_t compiler_start_time = jl_hrtime(); if (unspec->invoke == NULL) { jl_code_info_t *src = NULL; JL_GC_PUSH1(&src); @@ -367,6 +369,7 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec) } JL_GC_POP(); } + cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); // Might GC } @@ -388,6 +391,7 @@ jl_value_t *jl_dump_method_asm(jl_method_instance_t *mi, size_t world, // (using sentinel value `1` instead) // so create an exception here so we can print pretty our lies JL_LOCK(&codegen_lock); // also disables finalizers, to prevent any unexpected recursion + uint64_t compiler_start_time = jl_hrtime(); specfptr = (uintptr_t)codeinst->specptr.fptr; if (specfptr == 0) { jl_code_info_t *src = jl_type_infer(mi, world, 0); @@ -411,6 +415,7 @@ jl_value_t *jl_dump_method_asm(jl_method_instance_t *mi, size_t world, } JL_GC_POP(); } + cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); } if (specfptr != 0) From 306c407b623d0b6f51d6724ebb5cabc17733688c Mon Sep 17 00:00:00 2001 From: Ian Date: Sun, 20 Sep 2020 22:51:50 -0400 Subject: [PATCH 05/11] update relevant time reports in docs --- doc/src/manual/performance-tips.md | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/doc/src/manual/performance-tips.md b/doc/src/manual/performance-tips.md index 7039daec30a50..18787dd2f942c 100644 --- a/doc/src/manual/performance-tips.md +++ b/doc/src/manual/performance-tips.md @@ -70,7 +70,7 @@ julia> function sum_global() end; julia> @time sum_global() - 0.017705 seconds (15.28 k allocations: 694.484 KiB) + 0.009639 seconds (7.36 k allocations: 300.310 KiB, 98.32% compilation time) 496.84883432553846 julia> @time sum_global() @@ -106,15 +106,15 @@ julia> function sum_arg(x) end; julia> @time sum_arg(x) - 0.007701 seconds (821 allocations: 43.059 KiB) + 0.006202 seconds (4.18 k allocations: 217.860 KiB, 99.72% compilation time) 496.84883432553846 julia> @time sum_arg(x) - 0.000006 seconds (5 allocations: 176 bytes) + 0.000005 seconds (1 allocation: 16 bytes) 496.84883432553846 ``` -The 5 allocations seen are from running the `@time` macro itself in global scope. If we instead run +The 1 allocation seen is from running the `@time` macro itself in global scope. If we instead run the timing in a function, we can see that indeed no allocations are performed: ```jldoctest sumarg; filter = r"[0-9\.]+ seconds" From 5747bb4a797aee6eea3854e41b46beffc7f45e50 Mon Sep 17 00:00:00 2001 From: Ian Date: Sat, 26 Sep 2020 19:45:24 -0400 Subject: [PATCH 06/11] add compiletime macro --- base/exports.jl | 1 + base/timing.jl | 25 +++++++++++++++++++++++++ doc/src/base/base.md | 1 + test/misc.jl | 10 ++++++++++ 4 files changed, 37 insertions(+) diff --git a/base/exports.jl b/base/exports.jl index 121f42db09af9..dbe38b7f838de 100644 --- a/base/exports.jl +++ b/base/exports.jl @@ -970,6 +970,7 @@ export @timev, @elapsed, @allocated, + @compiletime, # tasks @sync, diff --git a/base/timing.jl b/base/timing.jl index 732e56b13f348..b9ab6f560029a 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -279,6 +279,31 @@ macro allocated(ex) end end +""" + @compiletime + +A macro to evaluate an expression, discarding the resulting value, instead returning the +total time in seconds of code generation during evaluation of the expression. + +See also [`@time`](@ref), [`@timev`](@ref), [`@timed`](@ref), +and [`@elapsed`](@ref). + +```julia-repl +julia> x = rand(10,10); + +julia> @compiletime x * x +0.54208595 +``` +""" +macro compiletime(ex) + quote + while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) + local t0 = cumulative_compile_time_ns() + local val = $(esc(ex)) + (cumulative_compile_time_ns() - t0) / 1e9 + end +end + """ @timed diff --git a/doc/src/base/base.md b/doc/src/base/base.md index 180c49f1315bf..e9d9fdbfbc338 100644 --- a/doc/src/base/base.md +++ b/doc/src/base/base.md @@ -303,6 +303,7 @@ Base.@timev Base.@timed Base.@elapsed Base.@allocated +Base.@compiletime Base.EnvDict Base.ENV Base.Sys.isunix diff --git a/test/misc.jl b/test/misc.jl index e5fc2f461643c..199776a446e18 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -186,6 +186,16 @@ let @test gcstats === stats.gcstats end +let + struct NewType + x::Array{Float64,2} + end + nt = NewType(rand(4,4)) + foo(nt::NewType) = nt.x * nt.x + @test (@compiletime foo(x)) > 0 # given NewType, this must include compilation + @test (@compiletime foo(x)) == 0 # given repeat, this must be compiled already +end + # problem after #11801 - at global scope t11801 = @elapsed 1+1 @test isa(t11801,Real) && t11801 >= 0 From e1d09a8e71decfe376713476436155ceeb3f1cd3 Mon Sep 17 00:00:00 2001 From: Ian Date: Sat, 26 Sep 2020 23:37:39 -0400 Subject: [PATCH 07/11] Revert "add compiletime macro" This reverts commit 5747bb4a797aee6eea3854e41b46beffc7f45e50. --- base/exports.jl | 1 - base/timing.jl | 25 ------------------------- doc/src/base/base.md | 1 - test/misc.jl | 10 ---------- 4 files changed, 37 deletions(-) diff --git a/base/exports.jl b/base/exports.jl index dbe38b7f838de..121f42db09af9 100644 --- a/base/exports.jl +++ b/base/exports.jl @@ -970,7 +970,6 @@ export @timev, @elapsed, @allocated, - @compiletime, # tasks @sync, diff --git a/base/timing.jl b/base/timing.jl index b9ab6f560029a..732e56b13f348 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -279,31 +279,6 @@ macro allocated(ex) end end -""" - @compiletime - -A macro to evaluate an expression, discarding the resulting value, instead returning the -total time in seconds of code generation during evaluation of the expression. - -See also [`@time`](@ref), [`@timev`](@ref), [`@timed`](@ref), -and [`@elapsed`](@ref). - -```julia-repl -julia> x = rand(10,10); - -julia> @compiletime x * x -0.54208595 -``` -""" -macro compiletime(ex) - quote - while false; end # compiler heuristic: compile this block (alter this if the heuristic changes) - local t0 = cumulative_compile_time_ns() - local val = $(esc(ex)) - (cumulative_compile_time_ns() - t0) / 1e9 - end -end - """ @timed diff --git a/doc/src/base/base.md b/doc/src/base/base.md index e9d9fdbfbc338..180c49f1315bf 100644 --- a/doc/src/base/base.md +++ b/doc/src/base/base.md @@ -303,7 +303,6 @@ Base.@timev Base.@timed Base.@elapsed Base.@allocated -Base.@compiletime Base.EnvDict Base.ENV Base.Sys.isunix diff --git a/test/misc.jl b/test/misc.jl index 199776a446e18..e5fc2f461643c 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -186,16 +186,6 @@ let @test gcstats === stats.gcstats end -let - struct NewType - x::Array{Float64,2} - end - nt = NewType(rand(4,4)) - foo(nt::NewType) = nt.x * nt.x - @test (@compiletime foo(x)) > 0 # given NewType, this must include compilation - @test (@compiletime foo(x)) == 0 # given repeat, this must be compiled already -end - # problem after #11801 - at global scope t11801 = @elapsed 1+1 @test isa(t11801,Real) && t11801 >= 0 From 27f4c114b63e03d494db1875aa8c7484e6328e35 Mon Sep 17 00:00:00 2001 From: Ian Date: Mon, 28 Sep 2020 17:21:24 -0400 Subject: [PATCH 08/11] tidy cpp code with += --- src/jitlayers.cpp | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/jitlayers.cpp b/src/jitlayers.cpp index cdc3f55d31d6d..d6bf220ca73a1 100644 --- a/src/jitlayers.cpp +++ b/src/jitlayers.cpp @@ -236,7 +236,7 @@ void jl_compile_extern_c(void *llvmmod, void *p, void *sysimg, jl_value_t *declr if (llvmmod == NULL) jl_add_to_ee(std::unique_ptr(into)); } - cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); + cumulative_compile_time += (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); } @@ -263,7 +263,7 @@ void jl_extern_c(jl_value_t *declrt, jl_tupletype_t *sigt) uint64_t compiler_start_time = jl_hrtime(); if (!jl_type_mappable_to_c(declrt)) jl_error("@ccallable: return type doesn't correspond to a C type"); - cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); + cumulative_compile_time += (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); // validate method signature @@ -329,7 +329,7 @@ jl_code_instance_t *jl_generate_fptr(jl_method_instance_t *mi JL_PROPAGATES_ROOT else { codeinst = NULL; } - cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); + cumulative_compile_time += (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); JL_GC_POP(); return codeinst; @@ -369,7 +369,7 @@ void jl_generate_fptr_for_unspecialized(jl_code_instance_t *unspec) } JL_GC_POP(); } - cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); + cumulative_compile_time += (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); // Might GC } @@ -415,7 +415,7 @@ jl_value_t *jl_dump_method_asm(jl_method_instance_t *mi, size_t world, } JL_GC_POP(); } - cumulative_compile_time = cumulative_compile_time + (jl_hrtime() - compiler_start_time); + cumulative_compile_time += (jl_hrtime() - compiler_start_time); JL_UNLOCK(&codegen_lock); } if (specfptr != 0) From 2eda4e18d03eda343c7c970694a4c158d16c0b2c Mon Sep 17 00:00:00 2001 From: Ian Date: Mon, 28 Sep 2020 17:22:42 -0400 Subject: [PATCH 09/11] replace example in docstring --- base/timing.jl | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index 732e56b13f348..2b87a88f99c29 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -149,7 +149,8 @@ end 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. +returning the value of the expression. If the time reported includes time spent doing +garbage collection (gc) or compilation, that will also be highlighted as a %. See also [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and [`@allocated`](@ref). @@ -160,8 +161,13 @@ See also [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and reduce noise. ```julia-repl -julia> @time rand(10^6); - 0.001525 seconds (7 allocations: 7.630 MiB) +julia> x = rand(10,10); + +julia> @time x * x; + 0.606588 seconds (2.19 M allocations: 116.555 MiB, 3.75% gc time, 99.94% compilation time) + +julia> @time x * x; + 0.000009 seconds (1 allocation: 896 bytes) julia> @time begin sleep(0.3) From edcd3a3bb042ae5c9a2171f3f7b9405deff56b1a Mon Sep 17 00:00:00 2001 From: Ian Date: Mon, 28 Sep 2020 17:46:55 -0400 Subject: [PATCH 10/11] update timev example --- base/timing.jl | 24 ++++++++++++++++++------ 1 file changed, 18 insertions(+), 6 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index 2b87a88f99c29..53df0c8a9c926 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -205,12 +205,24 @@ See also [`@time`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and [`@allocated`](@ref). ```julia-repl -julia> @timev rand(10^6); - 0.001006 seconds (7 allocations: 7.630 MiB) -elapsed time (ns): 1005567 -bytes allocated: 8000256 -pool allocs: 6 -malloc() calls: 1 +julia> x = rand(10,10); + +julia> @timev x * x; + 0.546770 seconds (2.20 M allocations: 116.632 MiB, 4.23% gc time, 99.94% compilation time) +elapsed time (ns): 546769547 +gc time (ns): 23115606 +bytes allocated: 122297811 +pool allocs: 2197930 +non-pool GC allocs:1327 +malloc() calls: 36 +realloc() calls: 5 +GC pauses: 3 + +julia> @timev x * x; + 0.000010 seconds (1 allocation: 896 bytes) +elapsed time (ns): 9848 +bytes allocated: 896 +pool allocs: 1 ``` """ macro timev(ex) From 5362f984c70f64d1d6eafe9963fe6f9317fd26b3 Mon Sep 17 00:00:00 2001 From: Ian Date: Tue, 29 Sep 2020 10:37:30 -0400 Subject: [PATCH 11/11] tweak docstring text and fix whitespace --- base/timing.jl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/base/timing.jl b/base/timing.jl index 53df0c8a9c926..ac932d01be121 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -149,8 +149,8 @@ end 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. If the time reported includes time spent doing -garbage collection (gc) or compilation, that will also be highlighted as a %. +returning the value of the expression. Any time spent garbage collecting (gc) or +compiling is shown as a percentage. See also [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ref), and [`@allocated`](@ref).