From 4ab0b9ee54513e250ffb1bef17659077d62b15bf Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sat, 18 Sep 2021 11:48:59 -0400
Subject: [PATCH 1/7] show mean in at-btime

---
 src/execution.jl | 13 ++++++++-----
 1 file changed, 8 insertions(+), 5 deletions(-)

diff --git a/src/execution.jl b/src/execution.jl
index d2346a66..c06e2c79 100644
--- a/src/execution.jl
+++ b/src/execution.jl
@@ -562,7 +562,7 @@ is the *minimum* elapsed time measured during the benchmark.
 macro btime(args...)
     _, params = prunekwargs(args...)
     bench, trial, result = gensym(), gensym(), gensym()
-    trialmin, trialallocs = gensym(), gensym()
+    trialmin, trialmean, trialallocs = gensym(), gensym(), gensym()
     tune_phase = hasevals(params) ? :() : :($BenchmarkTools.tune!($bench))
     return esc(quote
         local $bench = $BenchmarkTools.@benchmarkable $(args...)
@@ -570,12 +570,15 @@ macro btime(args...)
         $tune_phase
         local $trial, $result = $BenchmarkTools.run_result($bench)
         local $trialmin = $BenchmarkTools.minimum($trial)
+        local $trialmean = $BenchmarkTools.mean($trial)
         local $trialallocs = $BenchmarkTools.allocs($trialmin)
-        println("  ",
-                $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
+        println("  min ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
+                ", mean ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmean)),
                 " (", $trialallocs , " allocation",
-                $trialallocs == 1 ? "" : "s", ": ",
-                $BenchmarkTools.prettymemory($BenchmarkTools.memory($trialmin)), ")")
+                $trialallocs == 1 ? "" : "s", 
+                $trialallocs == 0 ? "" : ": " * 
+                    $BenchmarkTools.prettymemory($BenchmarkTools.memory($trialmin)), 
+                ")")
         $result
     end)
 end

From e557aab55ae1542f5418476a1672432c2538d31f Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sat, 18 Sep 2021 12:29:40 -0400
Subject: [PATCH 2/7] add GC time

---
 src/execution.jl | 18 +++++++++++-------
 src/trials.jl    |  8 ++++++--
 2 files changed, 17 insertions(+), 9 deletions(-)

diff --git a/src/execution.jl b/src/execution.jl
index c06e2c79..008995f7 100644
--- a/src/execution.jl
+++ b/src/execution.jl
@@ -572,13 +572,17 @@ macro btime(args...)
         local $trialmin = $BenchmarkTools.minimum($trial)
         local $trialmean = $BenchmarkTools.mean($trial)
         local $trialallocs = $BenchmarkTools.allocs($trialmin)
-        println("  min ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
-                ", mean ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmean)),
-                " (", $trialallocs , " allocation",
-                $trialallocs == 1 ? "" : "s", 
-                $trialallocs == 0 ? "" : ": " * 
-                    $BenchmarkTools.prettymemory($BenchmarkTools.memory($trialmin)), 
-                ")")
+        $print("  min ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
+            ", mean ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmean)),
+            " (", $trialallocs , " allocation", $trialallocs == 1 ? "" : "s")
+        if $trialallocs == 0
+            $println(")")
+        else
+            $println(", ", $prettymemory($memory($trialmin)),
+                ". GC mean ", $prettytime($gctime($trialmean); short=true),
+                ", ", $prettypercent($gctime($trialmean) / $time($trialmean)), ")"
+                )
+        end
         $result
     end)
 end
diff --git a/src/trials.jl b/src/trials.jl
index 639ee794..4787054d 100644
--- a/src/trials.jl
+++ b/src/trials.jl
@@ -253,7 +253,7 @@ function prettydiff(p)
     return string(diff >= 0.0 ? "+" : "", @sprintf("%.2f", diff * 100), "%")
 end
 
-function prettytime(t)
+function prettytime(t; short=false)
     if t < 1e3
         value, units = t, "ns"
     elseif t < 1e6
@@ -263,7 +263,11 @@ function prettytime(t)
     else
         value, units = t / 1e9, "s"
     end
-    return string(@sprintf("%.3f", value), " ", units)
+    if short
+        string(@sprintf("%.0f", value), " ", units)
+    else
+        string(@sprintf("%.3f", value), " ", units)
+    end
 end
 
 function prettymemory(b)

From 21888655fae6e8c62f5d20a12ec8b339d907a57a Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sat, 18 Sep 2021 16:42:41 -0400
Subject: [PATCH 3/7] docstring + tests

---
 src/execution.jl       | 24 ++++++++++++++++++++----
 src/trials.jl          |  2 +-
 test/ExecutionTests.jl | 17 ++++++++++++++++-
 3 files changed, 37 insertions(+), 6 deletions(-)

diff --git a/src/execution.jl b/src/execution.jl
index 008995f7..f128ceb0 100644
--- a/src/execution.jl
+++ b/src/execution.jl
@@ -554,10 +554,26 @@ this executes an expression, printing the time
 it took to execute and the memory allocated before
 returning the value of the expression.
 
-Unlike `@time`, it uses the `@benchmark`
-macro, and accepts all of the same additional
-parameters as `@benchmark`.  The printed time
-is the *minimum* elapsed time measured during the benchmark.
+However, it uses the [`@benchmark`](@ref) to evaluate
+`expression` many times, and accepts all of the same
+additional parameters as `@benchmark`. It prints both
+the minimum and the mean elapsed time, plus information
+about allocations (if any) and time spent on
+memory garbage collection (GC).
+
+# Examples
+```
+julia> @btime log(x[]) setup=(x=Ref(2.0))
+  min 3.666 ns, mean 3.772 ns (0 allocations)
+0.6931471805599453
+
+julia> @btime sum(log, \$(fill(2.0, 1000)))
+  min 3.391 μs, mean 3.441 μs (0 allocations)
+693.1471805599322
+
+julia> @btime rand(1000);
+  min 724.432 ns, mean 1.462 μs (1 allocation, 7.94 KiB. GC mean 352 ns, 24.11%)
+```
 """
 macro btime(args...)
     _, params = prunekwargs(args...)
diff --git a/src/trials.jl b/src/trials.jl
index 4787054d..3b9bcbf0 100644
--- a/src/trials.jl
+++ b/src/trials.jl
@@ -264,7 +264,7 @@ function prettytime(t; short=false)
         value, units = t / 1e9, "s"
     end
     if short
-        string(@sprintf("%.0f", value), " ", units)
+        string(@sprintf("%.0f", value), " ", units)  # "%.3g" also OK, always 3 numbers
     else
         string(@sprintf("%.3f", value), " ", units)
     end
diff --git a/test/ExecutionTests.jl b/test/ExecutionTests.jl
index 7b71c716..2932e89e 100644
--- a/test/ExecutionTests.jl
+++ b/test/ExecutionTests.jl
@@ -227,6 +227,7 @@ str = String(take!(io))
 
 let fname = tempname()
     try
+        # simple function, zero allocations
         ret = open(fname, "w") do f
             redirect_stdout(f) do
                 x = 1
@@ -238,7 +239,21 @@ let fname = tempname()
         end
         s = read(fname, String)
         try
-            @test occursin(r"[0-9.]+ \w*s \([0-9]* allocations?: [0-9]+ bytes\)", s)
+            @test occursin(r"min [0-9.]+ \w*s, mean [0-9.]+ \w*s \(0 allocations\)", s)
+        catch
+            println(stderr, "@btime output didn't match ", repr(s))
+            rethrow()
+        end
+        # function which allocates
+        ret2 = open(fname, "w") do f
+            redirect_stdout(f) do
+                y = @btime(sum(log, ones(100)))
+                @test y ≈ 0
+            end
+        end
+        s2 = read(fname, String)
+        try
+            @test occursin(r", mean [0-9.]+ \w*s \([0-9]* allocations?, [0-9]+ bytes. GC mean [0-9.]+ \w*s,", s2)
         catch
             println(stderr, "@btime output didn't match ", repr(s))
             rethrow()

From 6a18704109a0e9ab30dce31f24e2e2e13c2afcd1 Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sat, 2 Oct 2021 18:35:59 -0400
Subject: [PATCH 4/7] better it for GC, skip time just percentage

---
 src/execution.jl | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/src/execution.jl b/src/execution.jl
index f128ceb0..89f704dd 100644
--- a/src/execution.jl
+++ b/src/execution.jl
@@ -591,14 +591,16 @@ macro btime(args...)
         $print("  min ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
             ", mean ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmean)),
             " (", $trialallocs , " allocation", $trialallocs == 1 ? "" : "s")
-        if $trialallocs == 0
-            $println(")")
-        else
-            $println(", ", $prettymemory($memory($trialmin)),
-                ". GC mean ", $prettytime($gctime($trialmean); short=true),
-                ", ", $prettypercent($gctime($trialmean) / $time($trialmean)), ")"
+        if $trialallocs != 0
+            $print(", ", $prettymemory($memory($trialmin)))
+        end
+        if $gctime($trialmean) != 0
+            $print(". GC mean ",
+                # $prettytime($gctime($trialmean); short=true), ", ",
+                $prettypercent($gctime($trialmean) / $time($trialmean)),
                 )
         end
+        $println(")")
         $result
     end)
 end

From 6f98e920804b6ef26336279495ded647f36285e7 Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sat, 2 Oct 2021 18:42:37 -0400
Subject: [PATCH 5/7] bold times

---
 src/execution.jl | 9 ++++++---
 1 file changed, 6 insertions(+), 3 deletions(-)

diff --git a/src/execution.jl b/src/execution.jl
index 89f704dd..d154ec80 100644
--- a/src/execution.jl
+++ b/src/execution.jl
@@ -588,9 +588,12 @@ macro btime(args...)
         local $trialmin = $BenchmarkTools.minimum($trial)
         local $trialmean = $BenchmarkTools.mean($trial)
         local $trialallocs = $BenchmarkTools.allocs($trialmin)
-        $print("  min ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
-            ", mean ", $BenchmarkTools.prettytime($BenchmarkTools.time($trialmean)),
-            " (", $trialallocs , " allocation", $trialallocs == 1 ? "" : "s")
+        $print("  min ")
+        $printstyled($BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)); bold=true)
+        $print(", ")
+        $print("mean ")
+        $printstyled($BenchmarkTools.prettytime($BenchmarkTools.time($trialmean)); bold=true)
+        $print(" (", $trialallocs , " allocation", $trialallocs == 1 ? "" : "s")
         if $trialallocs != 0
             $print(", ", $prettymemory($memory($trialmin)))
         end

From 16667015e1dc6953f0a7f608db3046335c3ebc80 Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sun, 5 Dec 2021 14:50:02 -0500
Subject: [PATCH 6/7] maybe delete GC percentage to keep it short?

---
 src/execution.jl       | 6 ------
 test/ExecutionTests.jl | 2 +-
 2 files changed, 1 insertion(+), 7 deletions(-)

diff --git a/src/execution.jl b/src/execution.jl
index d154ec80..44404d71 100644
--- a/src/execution.jl
+++ b/src/execution.jl
@@ -597,12 +597,6 @@ macro btime(args...)
         if $trialallocs != 0
             $print(", ", $prettymemory($memory($trialmin)))
         end
-        if $gctime($trialmean) != 0
-            $print(". GC mean ",
-                # $prettytime($gctime($trialmean); short=true), ", ",
-                $prettypercent($gctime($trialmean) / $time($trialmean)),
-                )
-        end
         $println(")")
         $result
     end)
diff --git a/test/ExecutionTests.jl b/test/ExecutionTests.jl
index 2932e89e..626dbbeb 100644
--- a/test/ExecutionTests.jl
+++ b/test/ExecutionTests.jl
@@ -253,7 +253,7 @@ let fname = tempname()
         end
         s2 = read(fname, String)
         try
-            @test occursin(r", mean [0-9.]+ \w*s \([0-9]* allocations?, [0-9]+ bytes. GC mean [0-9.]+ \w*s,", s2)
+            @test occursin(r", mean [0-9.]+ \w*s \([0-9]* allocations?, [0-9]+ bytes", s2)
         catch
             println(stderr, "@btime output didn't match ", repr(s))
             rethrow()

From 6af30cf91fd6162c6b8d3799ecfb0b621c365034 Mon Sep 17 00:00:00 2001
From: Michael Abbott <32575566+mcabbott@users.noreply.github.com>
Date: Sun, 5 Dec 2021 14:50:27 -0500
Subject: [PATCH 7/7] docs

---
 docs/src/index.md  | 18 +++++++++---------
 docs/src/manual.md | 17 ++++++++++-------
 2 files changed, 19 insertions(+), 16 deletions(-)

diff --git a/docs/src/index.md b/docs/src/index.md
index a3da1678..f300aa56 100644
--- a/docs/src/index.md
+++ b/docs/src/index.md
@@ -33,7 +33,7 @@ For quick sanity checks, one can use the [`@btime` macro](https://github.com/Jul
 
 ```julia
 julia> @btime sin(x) setup=(x=rand())
-  4.361 ns (0 allocations: 0 bytes)
+  min 3.041 ns, mean 3.487 ns (0 allocations)
 0.49587200950472454
 ```
 
@@ -45,16 +45,16 @@ If the expression you want to benchmark depends on external variables, you shoul
 Essentially, any interpolated variable `$x` or expression `$(...)` is "pre-computed" before benchmarking begins:
 
 ```julia
-julia> A = rand(3,3);
+julia> A = rand(8,8);
 
 julia> @btime inv($A);            # we interpolate the global variable A with $A
-  1.191 μs (10 allocations: 2.31 KiB)
+  min 951.000 ns, mean 1.349 μs (4 allocations, 4.81 KiB)
 
-julia> @btime inv($(rand(3,3)));  # interpolation: the rand(3,3) call occurs before benchmarking
-  1.192 μs (10 allocations: 2.31 KiB)
+julia> @btime inv($(rand(8,8)));  # interpolation: the rand() call occurs before benchmarking
+  min 930.542 ns, mean 1.363 μs (4 allocations, 4.81 KiB)
 
-julia> @btime inv(rand(3,3));     # the rand(3,3) call is included in the benchmark time
-  1.295 μs (11 allocations: 2.47 KiB)
+julia> @btime inv(rand(8,8));     # the rand() call is included in the benchmark time
+  min 1.092 μs, mean 1.572 μs (5 allocations, 5.38 KiB)
 ```
 
 Sometimes, interpolating variables into very simple expressions can give the compiler more information than you intended, causing it to "cheat" the benchmark by hoisting the calculation out of the benchmark code
@@ -63,13 +63,13 @@ julia> a = 1; b = 2
 2
 
 julia> @btime $a + $b
-  0.024 ns (0 allocations: 0 bytes)
+  min 0.875 ns, mean 0.950 ns (0 allocations)
 3
 ```
 As a rule of thumb, if a benchmark reports that it took less than a nanosecond to perform, this hoisting probably occured. You can avoid this by referencing and dereferencing the interpolated variables 
 ```julia
 julia> @btime $(Ref(a))[] + $(Ref(b))[]
-  1.277 ns (0 allocations: 0 bytes)
+  min 0.875 ns, mean 0.953 ns (0 allocations)
 3
 ```
 
diff --git a/docs/src/manual.md b/docs/src/manual.md
index 8fd5105a..e62fad74 100644
--- a/docs/src/manual.md
+++ b/docs/src/manual.md
@@ -65,12 +65,15 @@ before returning the value of the expression, while `@belapsed`
 returns the minimum time in seconds.
 
 ```julia
-julia> @btime sin(1)
-  13.612 ns (0 allocations: 0 bytes)
-0.8414709848078965
+julia> @btime sin.(0:2)
+  min 25.687 ns, mean 28.266 ns (1 allocation, 80 bytes)
+3-element Vector{Float64}:
+ 0.0
+ 0.8414709848078965
+ 0.9092974268256817
 
-julia> @belapsed sin(1)
-1.3614228456913828e-8
+julia> @belapsed sin.(0:2)
+2.5727911646586344e-8
 ```
 
 ### Benchmark `Parameters`
@@ -280,13 +283,13 @@ julia> a = 1; b = 2
 2
 
 julia> @btime $a + $b
-  0.024 ns (0 allocations: 0 bytes)
+  min 0.833 ns, mean 0.944 ns (0 allocations)
 3
 ```
 in this case julia was able to use the properties of `+(::Int, ::Int)` to know that it could safely replace `$a + $b` with `3` at compile time. We can stop the optimizer from doing this by referencing and dereferencing the interpolated variables  
 ```julia
 julia> @btime $(Ref(a))[] + $(Ref(b))[]
-  1.277 ns (0 allocations: 0 bytes)
+  min 0.875 ns, mean 0.948 ns (0 allocations)
 3
 ```