Add TimerOutput to analyze doc build times

[jkrumbiegel]

Makie has switched back to Documenter(Vitepress), so I was reminded of the issue that I have no insight into the build time. We have tons of examples that can also be rather heavy, so my idea was to list all of them sorted by time using TimerOutputs.jl. This PR is for now just a draft of how this could look.

Here's an example output from a reduced run of the Makie docs, where one can see that the intervalslider page needs half the time due to a long video being rendered. (The lines can usually be shown but I'm mostly using a modified example block where the matching of the code back to the file breaks)

──────────────────────────────────────────────────────────────────────────────────────────────────────
 Section                                                                        ncalls     time    %tot
 ──────────────────────────────────────────────────────────────────────────────────────────────────────
 ExpandTemplates: expanding markdown templates.                                      1    38.2s   88.2%
   reference/blocks/intervalslider.md                                                1    24.0s   55.4%
     L58-109 @setup intervalslider using ..FakeInteraction events = [ Wait(1...      1    22.6s   52.2%
     L21-56 @example intervalslider using GLMakie f = Figure() Axis(f[1, 1],...      1    461ms    1.1%
   tutorials/layout-tutorial.md                                                      1    10.6s   24.5%
     @example layout rowsize!(gcd, 1, Auto(1.5)) f                                   1    1.68s    3.9%
     @example layout for (i, label) in enumerate(["sleep", "awake", "test"])...      1    1.01s    2.3%
     @example layout axs = [Axis(gd[row, col]) for row in 1:3, col in 1:2] h...      1    944ms    2.2%
     @example layout brain = load(assetpath("brain.stl")) ax3d = Axis3(gc[1,...      1    889ms    2.1%
     @example layout for (label, layout) in zip(["A", "B", "C", "D"], [ga, g...      1    808ms    1.9%
     @example layout n_day_1 = length(0:0.1:6pi) n_day_2 = length(0:0.1:10pi...      1    768ms    1.8%
     @example layout Label(gd[1, :, Top()], "EEG traces", valign = :bottom, ...      1    766ms    1.8%
     @example layout rowgap!(gd, 10) colgap!(gd, 10) f                               1    766ms    1.8%
     @example layout colgap!(gd, 2, 0) f                                             1    754ms    1.7%
     @example layout colsize!(f.layout, 1, Auto(0.5)) f                              1    738ms    1.7%
     @example layout xs = LinRange(0.5, 6, 50) ys = LinRange(0.5, 6, 50) dat...      1    227ms    0.5%
     @example layout axtop = Axis(ga[1, 1]) axmain = Axis(ga[2, 1], xlabel =...      1    146ms    0.3%
     @example layout cb = Colorbar(gb[1:2, 2], hm, label = "cell group") low...      1    139ms    0.3%
     @example layout colgap!(gb, 10) rowgap!(gb, 10) f                               1    135ms    0.3%
     @example layout cb.alignmode = Mixed(right = 0) f                               1    128ms    0.3%
     @example layout hidedecorations!(axtop, grid = false) hidedecorations!(...      1   98.5ms    0.2%
     @example layout leg = Legend(ga[1, 2], axmain) f                                1   98.4ms    0.2%
     @example layout ylims!(axtop, low = 0) xlims!(axright, low = 0) f               1   98.1ms    0.2%
     @example layout Label(ga[1, 1:2, Top()], "Stimulus ratings", valign = :...      1   96.7ms    0.2%
     @example layout colgap!(ga, 10) rowgap!(ga, 10) f                               1   93.8ms    0.2%
     @example layout axmain.xticks = 0:3:9 axtop.xticks = 0:3:9 f                    1   92.3ms    0.2%
     @example layout using CairoMakie using FileIO f = Figure(backgroundcolo...      1   90.8ms    0.2%
     L174-181 @example layout ga = f[1, 1] = GridLayout() gb = f[2, 1] = Gri...      1   4.77ms    0.0%
   tutorials/basic-tutorial.md                                                       1    1.66s    3.8%
     @example basic  using CairoMakie fig, ax, hm = heatmap(randn(20, 20)) C...      1    199ms    0.5%
     @example basic  using CairoMakie x = LinRange(0, 10, 100) y = sin.(x) f...      1   66.5ms    0.2%
     @example basic  using CairoMakie fig = Figure() ax1, l1 = lines(fig[1, ...      1   66.3ms    0.2%
     @example basic  using CairoMakie x = range(0, 10, length=100) lines(x, ...      1   59.6ms    0.1%
     @example basic x = range(0, 10, length=100) f, ax, l1 = lines(x, sin) l...      1   54.1ms    0.1%
     @example basic  using CairoMakie fig = Figure() ax1 = Axis(fig[1, 1]) a...      1   53.9ms    0.1%
     @example basic x = range(0, 10, length=100) f, ax, l1 = lines(x, sin) l...      1   51.9ms    0.1%
     @example basic x = range(0, 10, length=100) f, ax, l1 = lines(x, sin, c...      1   51.3ms    0.1%
     @example basic x = range(0, 10, length=100) f, ax, sc1 = scatter(x, sin...      1   51.2ms    0.1%
     @example basic sc1.marker = :utriangle sc1.markersize = 20 sc2.color = ...      1   50.0ms    0.1%
     @example basic  using CairoMakie x = range(0, 10, length=100) colors = ...      1   49.9ms    0.1%
     @example basic  lines!(ax1, 0..10, sin) lines!(ax2, 0..10, cos) lines!(...      1   49.5ms    0.1%
     @example basic  using CairoMakie fig = Figure() ax = Axis(fig[1, 1]) hm...      1   49.2ms    0.1%
     @example basic lines(0..10, sin)                                                1   48.4ms    0.1%
     @example basic x = range(0, 10, length=100) scatter(x, sin, markersize ...      1   48.2ms    0.1%
     @example basic figure, axis, lineplot = lines(x, y) figure                      1   48.2ms    0.1%
     @example basic x = range(0, 10, length=100) scatter(x, sin, markersize ...      1   47.8ms    0.1%
     @example basic f = Figure() ax = Axis(f[1, 1]) x = range(0, 10, length=...      1   47.3ms    0.1%
     @example basic x = range(0, 10, length=100) y = sin.(x) lines(x, y)             1   47.1ms    0.1%
     @example basic lines(0:1:10, cos)                                               1   47.1ms    0.1%
     @example basic f = Figure() ax = Axis(f[1, 1]) x = range(0, 10, length=...      1   46.0ms    0.1%
     @example basic lines([Point(0, 0), Point(5, 10), Point(10, 5)])                 1   45.1ms    0.1%
     @example basic f = Figure() ax = Axis(f[1, 1], title = "A Makie Axis", ...      1   42.2ms    0.1%
     @example basic f = Figure() ax = Axis(f[1, 1]) f                                1   41.7ms    0.1%
     @example basic x = range(0, 10, length=100) y = sin.(x) scatter(x, y; f...      1   36.9ms    0.1%
     @example basic f = Figure(backgroundcolor = :tomato)                            1   35.1ms    0.1%
     @example basic f = Figure(backgroundcolor = :tomato, size = (800, 300))         1   31.5ms    0.1%
     L28-33 @example basic using CairoMakie nothing # hide                           1   1.91ms    0.0%
   tutorials/aspect-tutorial.md                                                      1    879ms    2.0%
     @example aspect f = Figure() for i in 1:5, j in 1:5 Axis(f[i, j], width...      1    228ms    0.5%
     @example aspect resize_to_layout!(f) f                                          2    188ms    0.4%
     @example aspect f = Figure(size = (800, 500)) ax = Axis(f[1, 1]) Colorb...      2    131ms    0.3%
     @example aspect Box(f[1, 1], color = (:red, 0.2), strokewidth = 0) f            2    121ms    0.3%
     @example aspect using CairoMakie set_theme!(backgroundcolor = :gray90) ...      1   71.0ms    0.2%
     @example aspect colsize!(f.layout, 1, Aspect(1, 0.5)) f                         1   55.1ms    0.1%
     @example aspect ax.aspect = 0.5 f                                               1   54.0ms    0.1%
   tutorials/scenes.md                                                               1    577ms    1.3%
     @example scenes screen = display(scene) # use display, to get a referen...      1    131ms    0.3%
     @example scenes campixel!(scene) w, h = size(scene) # get the size of t...      1   98.4ms    0.2%
     @example scenes figure, axis, plot_object = scatter(1:4) relative_proje...      1   84.5ms    0.2%
     @example scenes using GLMakie scene = Scene(backgroundcolor=:gray) subw...      1   39.3ms    0.1%
     @example scenes parent = Scene() cam3d!(parent; clipping_mode = :static...      1   26.0ms    0.1%
     @example scenes scene = Scene(backgroundcolor=:gray) lines!(scene, Rect...      1   24.3ms    0.1%
     @example scenes cam.projection[] = Makie.orthographicprojection(-3f0, 5...      1   24.1ms    0.1%
     @example scenes scene = Scene() cam3d!(scene) sphere_plot = mesh!(scene...      1   23.0ms    0.1%
     @example scenes subwindow.clear = false relative_space = Makie.camrelat...      1   22.4ms    0.1%
     @example scenes translate!(scene.plots[1], 0, 0, -10000) scene                  1   20.0ms    0.0%
     @example scenes cam3d!(subwindow) meshscatter!(subwindow, rand(Point3f,...      1   19.9ms    0.0%
     @example scenes # Now, rotate the "joints" rotate!(s2, Vec3f(0, 1, 0), ...      1   17.1ms    0.0%
     @example scenes translate!(sphere_plot, Vec3f(0, 0, 1)) scene                   1   16.8ms    0.0%
     @example scenes w, h = size(scene) nearplane = 0.1f0 farplane = 100f0 a...      1   16.7ms    0.0%
     L102-104 @example scenes scene.events                                           1   3.66ms    0.0%
     L129-131 @example scenes cam = Makie.camera(scene) # this is how to acc...      1    853μs    0.0%
   tutorials/wrap-existing-recipe.md                                                 1    532ms    1.2%
     @example recipe function Makie.plot!(plot::Hist{<:Tuple{<:MyHist}}) bar...      1    313ms    0.7%

[goerz]

I like the idea!

[mortenpi]

This seems pretty great! I need to find some time to go through the implementation, but generally I don't think I have any reservations about it (except the global state). This is looking pretty good already!

[jkrumbiegel]

Yeah maybe scoped values would be appropriate here? Although they might be too new for Documenter, that's why I didn't try them.

Another question I had was if the implementation could be pushed outside of all the runner functions. But I needed some info that was already available inside, like line numbers, and I didn't want to duplicate that. Maybe there's a trick how the timing code can be placed more elegantly.

[GeorgeR227]

I've run this branch on my own documentation. Everything seems to build correctly and the timing output is also very informative. I will mention however that the docs I ran don't have any doctesting so I can't speak if that works or not with this branch.

My only thought was that since the timing table output can get quite large, maybe there should be an option to disable the benchmarking or to collapse the table output to be by page only.

[goerz]

I would probably make it opt-in with an option in makedocs

[jkrumbiegel]

A simple api that makes it less global could be to pass in a TimerOutput or simply a Ref() via a keyword which at the end holds all the measurements. The user could then do whatever with it, just print it as is, or postprocess it. And you don't have to change the return type of makedocs.

I thought some useful post processing might be to remove all code blocks under some threshold of either absolute time or percentage of page. Because you're going to care about the 20% of code using 80% of the time.

[jkrumbiegel]

The way I have it refactored now is that there are two levels (aside from no timings) and with full timings you get timings for every block, for the other one just for every page.

makedocs(;
    sitename = "Some Site",
    timings = Documenter.BasicTimings,
)

────────────────────────────────────────────────────────────────────────
 Section                                          ncalls     time    %tot
 ────────────────────────────────────────────────────────────────────────
 ExpandTemplates: expanding markdown templates.        1    3.22s   98.3%
   index.md                                            1    3.22s   98.3%
 RenderDocument: rendering document.                   1   54.5ms    1.7%
 SetupBuildDirectory                                   1   2.21ms    0.1%
 Doctest: running doctests.                            1   40.6μs    0.0%
 CheckDocument: running document checks.               1   32.8μs    0.0%
 CrossReferences: building cross-references.           1   24.6μs    0.0%
 ────────────────────────────────────────────────────────────────────────

makedocs(;
    sitename = "Some Site",
    timings = Documenter.FullTimings,
)

────────────────────────────────────────────────────────────────────────
 Section                                          ncalls     time    %tot
 ────────────────────────────────────────────────────────────────────────
 ExpandTemplates: expanding markdown templates.        1    3.22s   98.6%
   index.md                                            1    3.22s   98.6%
     L1-4 @example sleep(2) sleep(0.1)                 1    2.11s   64.5%
     L6-12 @example sleep(1) # more # code # m...      1    1.00s   30.7%
     L14-16 @setup name 1 + 1                          1    835μs    0.0%
 RenderDocument: rendering document.                   1   44.8ms    1.4%
 SetupBuildDirectory                                   1   2.53ms    0.1%
 Doctest: running doctests.                            1   26.0μs    0.0%
 CheckDocument: running document checks.               1   9.08μs    0.0%
 CrossReferences: building cross-references.           1   2.79μs    0.0%
 ────────────────────────────────────────────────────────────────────────

I was already halfway started to make a more complicated system where you can filter even more and come up with custom selections, but then I thought that's probably way overkill.