diff --git a/README.md b/README.md index af55558a..3bafe04e 100644 --- a/README.md +++ b/README.md @@ -50,18 +50,17 @@ julia> using BenchmarkTools # The `setup` expression is run once per sample, and is not included in the # timing results. Note that each sample can require multiple evaluations # benchmark kernel evaluations. See the BenchmarkTools manual for details. -julia> @benchmark sin(x) setup=(x=rand()) -BenchmarkTools.Trial: - memory estimate: 0 bytes - allocs estimate: 0 - -------------- - minimum time: 4.248 ns (0.00% GC) - median time: 4.631 ns (0.00% GC) - mean time: 5.502 ns (0.00% GC) - maximum time: 60.995 ns (0.00% GC) - -------------- - samples: 10000 - evals/sample: 1000 +julia> @benchmark sort(data) setup=(data=rand(10)) +BechmarkTools.Trial: + 10000 samples with 968 evaulations took a median time of 90.902 ns (0.00% GC) + Time (mean ± σ): 94.936 ns ± 47.797 ns (GC: 2.78% ± 5.03%) + Range (min … max): 77.655 ns … 954.823 ns (GC: 0.00% … 87.94%) + + ▁▃▅▆▇█▇▆▅▂▁ + ▂▂▃▃▄▅▆▇███████████▇▆▄▄▃▃▂▂▂▂▂▂▂▂▂▂▂▁▂▁▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂ + 77.7 ns Histogram: frequency by time 137 ns + + Memory estimate: 160 bytes, allocs estimate: 1. ``` For quick sanity checks, one can use the [`@btime` macro](https://github.com/JuliaCI/BenchmarkTools.jl/blob/master/doc/manual.md#benchmarking-basics), which is a convenience wrapper around `@benchmark` whose output is analogous to Julia's built-in [`@time` macro](https://docs.julialang.org/en/v1/base/base/#Base.@time): diff --git a/docs/src/index.md b/docs/src/index.md index 0bb2373b..05dc2ff6 100644 --- a/docs/src/index.md +++ b/docs/src/index.md @@ -16,18 +16,17 @@ julia> using BenchmarkTools # The `setup` expression is run once per sample, and is not included in the # timing results. Note that each sample can require multiple evaluations # benchmark kernel evaluations. See the BenchmarkTools manual for details. -julia> @benchmark sin(x) setup=(x=rand()) -BenchmarkTools.Trial: - memory estimate: 0 bytes - allocs estimate: 0 - -------------- - minimum time: 4.248 ns (0.00% GC) - median time: 4.631 ns (0.00% GC) - mean time: 5.502 ns (0.00% GC) - maximum time: 60.995 ns (0.00% GC) - -------------- - samples: 10000 - evals/sample: 1000 +julia> @benchmark sort(data) setup=(data=rand(10)) +BechmarkTools.Trial: + 10000 samples with 968 evaulations took a median time of 90.902 ns (0.00% GC) + Time (mean ± σ): 94.936 ns ± 47.797 ns (GC: 2.78% ± 5.03%) + Range (min … max): 77.655 ns … 954.823 ns (GC: 0.00% … 87.94%) + + ▁▃▅▆▇█▇▆▅▂▁ + ▂▂▃▃▄▅▆▇███████████▇▆▄▄▃▃▂▂▂▂▂▂▂▂▂▂▂▁▂▁▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂ + 77.7 ns Histogram: frequency by time 137 ns + + Memory estimate: 160 bytes, allocs estimate: 1. ``` For quick sanity checks, one can use the [`@btime` macro](https://github.com/JuliaCI/BenchmarkTools.jl/blob/master/doc/manual.md#benchmarking-basics), which is a convenience wrapper around `@benchmark` whose output is analogous to Julia's built-in [`@time` macro](https://docs.julialang.org/en/v1/base/base/#Base.@time): diff --git a/src/trials.jl b/src/trials.jl index 9040a084..25f37c72 100644 --- a/src/trials.jl +++ b/src/trials.jl @@ -120,6 +120,7 @@ end Statistics.median(trial::Trial) = TrialEstimate(trial, median(trial.times), median(trial.gctimes)) Statistics.mean(trial::Trial) = TrialEstimate(trial, mean(trial.times), mean(trial.gctimes)) +Statistics.std(trial::Trial) = TrialEstimate(trial, std(trial.times), std(trial.gctimes)) Base.isless(a::TrialEstimate, b::TrialEstimate) = isless(time(a), time(b)) @@ -289,6 +290,32 @@ function withtypename(f, io, t) end end +function bindata(sorteddata, nbins) + min, max = sorteddata[[1; end]] + Δ = (max - min) / nbins + bins = zeros(nbins) + lastpos = 0 + for i ∈ 1:nbins + pos = searchsortedlast(sorteddata, min + i * Δ) + bins[i] = pos - lastpos + lastpos = pos + end + bins +end + +function asciihist(bins, height=1) + histbars = ['▁', '▂', '▃', '▄', '▅', '▆', '▇', '█'] + if minimum(bins) == 0 + barheights = 2 .+ round.(Int, (height * length(histbars) - 2) * bins ./ maximum(bins)) + barheights[bins .== 0] .= 1 + else + barheights = 1 .+ round.(Int, (height * length(histbars) - 1) * bins ./ maximum(bins)) + end + [let bheight = barheights[b] - (h-1) * length(histbars) + bheight < 1 ? ' ' : histbars[minimum([length(histbars), bheight])] + end for h in height:-1:1, b in 1:length(bins)] +end + _summary(io, t, args...) = withtypename(() -> print(io, args...), io, t) Base.summary(io::IO, t::Trial) = _summary(io, t, prettytime(time(t))) @@ -313,36 +340,139 @@ Base.show(io::IO, t::TrialJudgement) = _show(io, t) function Base.show(io::IO, ::MIME"text/plain", t::Trial) if length(t) > 0 - min = minimum(t) - max = maximum(t) med = median(t) avg = mean(t) + std = Statistics.std(t) + min = minimum(t) + max = maximum(t) + + medtime, medgc = prettytime(time(med)), prettypercent(gcratio(med)) + avgtime, avggc = prettytime(time(avg)), prettypercent(gcratio(avg)) + stdtime, stdgc = prettytime(time(std)), prettypercent(Statistics.std(t.gctimes ./ t.times)) + mintime, mingc = prettytime(time(min)), prettypercent(gcratio(min)) + maxtime, maxgc = prettytime(time(max)), prettypercent(gcratio(max)) + memorystr = string(prettymemory(memory(min))) allocsstr = string(allocs(min)) - minstr = string(prettytime(time(min)), " (", prettypercent(gcratio(min)), " GC)") - maxstr = string(prettytime(time(max)), " (", prettypercent(gcratio(max)), " GC)") - medstr = string(prettytime(time(med)), " (", prettypercent(gcratio(med)), " GC)") - meanstr = string(prettytime(time(avg)), " (", prettypercent(gcratio(avg)), " GC)") else - memorystr = "N/A" - allocsstr = "N/A" - minstr = "N/A" - maxstr = "N/A" - medstr = "N/A" - meanstr = "N/A" + medtime, medgc = "N/A", "N/A" + avgtime, avggc = "N/A", "N/A" + stdtime, stdgc = "N/A", "N/A" + mintime, mingc = "N/A", "N/A" + maxtime, maxgc = "N/A", "N/A" + memorystr, allocsstr = "N/A", "N/A" end - println(io, "BenchmarkTools.Trial: ") + + lmaxtimewidth = maximum(length.([medtime, avgtime, mintime])) + rmaxtimewidth = maximum(length.([stdtime, maxtime])) + lmaxgcwidth = maximum(length.([medgc, avggc, mingc])) + rmaxgcwidth = maximum(length.([stdgc, maxgc])) + + # Main stats + pad = get(io, :pad, "") - println(io, pad, " memory estimate: ", memorystr) - println(io, pad, " allocs estimate: ", allocsstr) - println(io, pad, " --------------") - println(io, pad, " minimum time: ", minstr) - println(io, pad, " median time: ", medstr) - println(io, pad, " mean time: ", meanstr) - println(io, pad, " maximum time: ", maxstr) - println(io, pad, " --------------") - println(io, pad, " samples: ", length(t)) - print(io, pad, " evals/sample: ", t.params.evals) + print(io, "BechmarkTools.Trial: ") + printstyled(io, length(t); bold=true) + print(io, " samples with ") + printstyled(io, t.params.evals; bold=true) + print(io, " evaluations.") + + print(io, "\n", pad, " Time ") + printstyled(io, "("; color=:light_black) + printstyled(io, "median"; color=:blue, bold=true) + printstyled(io, "): "; color=:light_black) + printstyled(io, lpad(medtime, lmaxtimewidth), rpad(" ", rmaxtimewidth + 5); color=:blue, bold=true) + printstyled(io, "┊"; color=:light_black) + print(io, " GC ") + printstyled(io, "("; color=:light_black) + print(io, "median") + printstyled(io, "): "; color=:light_black) + print(io, lpad(medgc, lmaxgcwidth)) + + print(io, "\n", pad, " Time ") + printstyled(io, "("; color=:light_black) + printstyled(io, "mean"; color=:green, bold=true) + print(io, " ± ") + printstyled(io, "σ"; color=:green) + printstyled(io, "): "; color=:light_black) + printstyled(io, lpad(avgtime, lmaxtimewidth); color=:green, bold=true) + print(io, " ± ") + printstyled(io, lpad(stdtime, rmaxtimewidth); color=:green) + print(io, " ") + printstyled(io, "┊"; color=:light_black) + print(io, " GC ") + printstyled(io, "("; color=:light_black) + print(io, "mean ± σ") + printstyled(io, "): "; color=:light_black) + print(io, lpad(avggc, lmaxgcwidth), " ± ", lpad(stdgc, rmaxgcwidth)) + + print(io, "\n", pad, " Range ") + printstyled(io, "("; color=:light_black) + printstyled(io, "min"; color=:cyan, bold=true) + print(io, " … ") + printstyled(io, "max"; color=:magenta) + printstyled(io, "): "; color=:light_black) + printstyled(io, lpad(mintime, lmaxtimewidth); color=:cyan, bold=true) + print(io, " … ") + printstyled(io, lpad(maxtime, rmaxtimewidth); color=:magenta) + print(io, " ") + printstyled(io, "┊"; color=:light_black) + print(io, " GC ") + printstyled(io, "("; color=:light_black) + print(io, "min … max") + printstyled(io, "): "; color=:light_black) + print(io, lpad(mingc, lmaxgcwidth), " … ", lpad(maxgc, rmaxgcwidth)) + + # Histogram + + histtimes = t.times[1:round(Int, 0.99*end)] + totalwidth = 45 + lmaxtimewidth + rmaxtimewidth + bins, logbins = bindata(histtimes, totalwidth), false + # if median size of (bins with >10% average data/bin) is less than 5% of max bin size, log the bin sizes + if median(filter(b -> b > 0.1 * length(t.times) / totalwidth, bins)) / maximum(bins) < 0.05 + bins, logbins = log.(1 .+ bins), true + end + hist = asciihist(bins, 2) + maxbin = maximum(bins) + + delta1 = (histtimes[end] - histtimes[1]) / (totalwidth - 1) + medpos = 1 + round(Int, (histtimes[length(histtimes) ÷ 2] - histtimes[1]) / delta1) + avgpos = 1 + round(Int, (mean(histtimes) - histtimes[1]) / delta1) + + print(io, "\n") + for histrow in eachrow(hist) + print(io, "\n", pad, " ") + for (i, bar) in enumerate(histrow) + color = :default + if i == avgpos color = :green end + if i == medpos color = :blue end + printstyled(io, bar; color=color) + end + end + + function remtrailingzeros(timestr) + if ! isnothing(match(r"\.0+", timestr)) + replace(timestr, r"\.0+" => "") + else + replace(timestr, r"(\.\d+?)0+" => s"\1") + end + end + minhisttime, maxhisttime = remtrailingzeros.(prettytime.(round.(histtimes[[1; end]], sigdigits=3))) + + caption = "Histogram: " * ( logbins ? "log(frequency)" : "frequency" ) * " by time" + print(io, "\n", pad, " ", minhisttime) + printstyled(io, " " ^ ((totalwidth - length(caption)) ÷ 2 - length(minhisttime)), caption; color=:light_black) + print(io, lpad(maxhisttime, ceil(Int, (totalwidth - length(caption)) / 2))) + + # Memory info + + print(io, "\n\n", pad, " Memory estimate") + printstyled(io, ": "; color=:light_black) + printstyled(io, memorystr; color=:yellow) + print(io, ", allocs estimate") + printstyled(io, ": "; color=:light_black) + printstyled(io, allocsstr; color=:yellow) + print(io, ".") end function Base.show(io::IO, ::MIME"text/plain", t::TrialEstimate)