Add TimerOutput to analyze doc build times

Project.toml

@@ -25,6 +25,7 @@ RegistryInstances = "2792f1a3-b283-48e8-9a74-f99dce5104f3"
 SHA = "ea8e919c-243c-51af-8825-aaa63cd721ce"
 TOML = "fa267f1f-6049-4f14-aa54-33bafae1ed76"
 Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
+TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f"
 Unicode = "4ec0a83e-493e-50e2-b9ac-8f72acf5a8f5"
 
 [compat]

src/Documenter.jl

@@ -23,6 +23,7 @@ import Unicode
 import Pkg
 import RegistryInstances
 import Git
+import TimerOutputs
 # Additional imported names
 using Test: @testset, @test
 using DocStringExtensions: SIGNATURES, EXPORTS

src/builder_pipeline.jl

@@ -74,83 +74,85 @@ Selectors.strict(::Type{T}) where {T <: Builder.DocumentPipeline} = false
 function Selectors.runner(::Type{Builder.SetupBuildDirectory}, doc::Documenter.Document)
     @info "SetupBuildDirectory: setting up build directory."
 
-    # Frequently used fields.
-    build  = doc.user.build
-    source = doc.user.source
-    workdir = doc.user.workdir
-
-    # The .user.source directory must exist.
-    isdir(source) || error("source directory '$(abspath(source))' is missing.")
-
-    # We create the .user.build directory.
-    # If .user.clean is set, we first clean the existing directory.
-    doc.user.clean && isdir(build) && rm(build; recursive = true)
-    isdir(build) || mkpath(build)
-
-    # We'll walk over all the files in the .user.source directory.
-    # The directory structure is copied over to .user.build. All files, with
-    # the exception of markdown files (identified by the extension) are copied
-    # over as well, since they're assumed to be images, data files etc.
-    # Markdown files, however, get added to the document and also stored into
-    # `mdpages`, to be used later.
-    mdpages = String[]
-    for (root, dirs, files) in walkdir(source)
-        for dir in dirs
-            d = normpath(joinpath(build, relpath(root, source), dir))
-            isdir(d) || mkdir(d)
-        end
-        for file in files
-            src = normpath(joinpath(root, file))
-            dst = normpath(joinpath(build, relpath(root, source), file))
-
-            if workdir == :build
-                # set working directory to be the same as `build`
-                wd = normpath(joinpath(build, relpath(root, source)))
-            elseif workdir isa Symbol
-                # Maybe allow `:src` and `:root` as well?
-                throw(ArgumentError("Unrecognized working directory option '$workdir'"))
-            else
-                wd = normpath(joinpath(doc.user.root, workdir))
+    @time_basic doc "SetupBuildDirectory" begin
+        # Frequently used fields.
+        build  = doc.user.build
+        source = doc.user.source
+        workdir = doc.user.workdir
+
+        # The .user.source directory must exist.
+        isdir(source) || error("source directory '$(abspath(source))' is missing.")
+
+        # We create the .user.build directory.
+        # If .user.clean is set, we first clean the existing directory.
+        doc.user.clean && isdir(build) && rm(build; recursive = true)
+        isdir(build) || mkpath(build)
+
+        # We'll walk over all the files in the .user.source directory.
+        # The directory structure is copied over to .user.build. All files, with
+        # the exception of markdown files (identified by the extension) are copied
+        # over as well, since they're assumed to be images, data files etc.
+        # Markdown files, however, get added to the document and also stored into
+        # `mdpages`, to be used later.
+        mdpages = String[]
+        for (root, dirs, files) in walkdir(source)
+            for dir in dirs
+                d = normpath(joinpath(build, relpath(root, source), dir))
+                isdir(d) || mkdir(d)
             end
-
-            if endswith(file, ".md")
-                push!(mdpages, Documenter.srcpath(source, root, file))
-                Documenter.addpage!(doc, src, dst, wd)
-            else
-                cp(src, dst; force = true)
+            for file in files
+                src = normpath(joinpath(root, file))
+                dst = normpath(joinpath(build, relpath(root, source), file))
+
+                if workdir == :build
+                    # set working directory to be the same as `build`
+                    wd = normpath(joinpath(build, relpath(root, source)))
+                elseif workdir isa Symbol
+                    # Maybe allow `:src` and `:root` as well?
+                    throw(ArgumentError("Unrecognized working directory option '$workdir'"))
+                else
+                    wd = normpath(joinpath(doc.user.root, workdir))
+                end
+
+                if endswith(file, ".md")
+                    push!(mdpages, Documenter.srcpath(source, root, file))
+                    Documenter.addpage!(doc, src, dst, wd)
+                else
+                    cp(src, dst; force = true)
+                end
             end
         end
-    end
 
-    # If the user hasn't specified the page list, then we'll just default to a
-    # flat list of all the markdown files we found, sorted by the filesystem
-    # path (it will group them by subdirectory, among others).
-    userpages = isempty(doc.user.pages) ? sort(mdpages, lt=lt_page) : doc.user.pages
+        # If the user hasn't specified the page list, then we'll just default to a
+        # flat list of all the markdown files we found, sorted by the filesystem
+        # path (it will group them by subdirectory, among others).
+        userpages = isempty(doc.user.pages) ? sort(mdpages, lt=lt_page) : doc.user.pages
 
-    # Populating the .navtree and .navlist.
-    # We need the for loop because we can't assign to the fields of the immutable
-    # doc.internal.
-    for navnode in walk_navpages(userpages, nothing, doc)
-        push!(doc.internal.navtree, navnode)
-    end
+        # Populating the .navtree and .navlist.
+        # We need the for loop because we can't assign to the fields of the immutable
+        # doc.internal.
+        for navnode in walk_navpages(userpages, nothing, doc)
+            push!(doc.internal.navtree, navnode)
+        end
 
-    # Finally we populate the .next and .prev fields of the navnodes that point
-    # to actual pages.
-    local prev::Union{Documenter.NavNode, Nothing} = nothing
-    for navnode in doc.internal.navlist
-        navnode.prev = prev
-        if prev !== nothing
-            prev.next = navnode
+        # Finally we populate the .next and .prev fields of the navnodes that point
+        # to actual pages.
+        local prev::Union{Documenter.NavNode, Nothing} = nothing
+        for navnode in doc.internal.navlist
+            navnode.prev = prev
+            if prev !== nothing
+                prev.next = navnode
+            end
+            prev = navnode
         end
-        prev = navnode
-    end
 
-    # If the user specified pagesonly, we will remove all the pages not in the navigation
-    # menu (.pages).
-    if doc.user.pagesonly
-        navlist_pages = getfield.(doc.internal.navlist, :page)
-        for page in keys(doc.blueprint.pages)
-            page ∈ navlist_pages || delete!(doc.blueprint.pages, page)
+        # If the user specified pagesonly, we will remove all the pages not in the navigation
+        # menu (.pages).
+        if doc.user.pagesonly
+            navlist_pages = getfield.(doc.internal.navlist, :page)
+            for page in keys(doc.blueprint.pages)
+                page ∈ navlist_pages || delete!(doc.blueprint.pages, page)
+            end
         end
     end
 end
@@ -206,7 +208,9 @@ walk_navpages(src::String, parent, doc) = walk_navpages(true, nothing, src, [],
 function Selectors.runner(::Type{Builder.Doctest}, doc::Documenter.Document)
     if doc.user.doctest in [:fix, :only, true]
         @info "Doctest: running doctests."
-        _doctest(doc.blueprint, doc)
+        @time_basic doc "Doctest: running doctests." begin
+            _doctest(doc.blueprint, doc)
+        end
         num_errors = length(doc.internal.errors)
         if (doc.user.doctest === :only || is_strict(doc, :doctest)) && num_errors > 0
             error("`makedocs` encountered $(num_errors > 1 ? "$(num_errors) doctest errors" : "a doctest error"). Terminating build")
@@ -219,22 +223,24 @@ end
 function Selectors.runner(::Type{Builder.ExpandTemplates}, doc::Documenter.Document)
     is_doctest_only(doc, "ExpandTemplates") && return
     @info "ExpandTemplates: expanding markdown templates."
-    expand(doc)
+    @time_basic doc "ExpandTemplates: expanding markdown templates." expand(doc)
 end
 
 function Selectors.runner(::Type{Builder.CrossReferences}, doc::Documenter.Document)
     is_doctest_only(doc, "CrossReferences") && return
     @info "CrossReferences: building cross-references."
-    crossref(doc)
+    @time_basic doc "CrossReferences: building cross-references." crossref(doc)
 end
 
 function Selectors.runner(::Type{Builder.CheckDocument}, doc::Documenter.Document)
     is_doctest_only(doc, "CheckDocument") && return
     @info "CheckDocument: running document checks."
-    missingdocs(doc)
-    footnotes(doc)
-    linkcheck(doc)
-    githubcheck(doc)
+    @time_basic doc "CheckDocument: running document checks." begin 
+        missingdocs(doc)
+        footnotes(doc)
+        linkcheck(doc)
+        githubcheck(doc)
+    end
 end
 
 function Selectors.runner(::Type{Builder.Populate}, doc::Documenter.Document)
@@ -255,7 +261,7 @@ function Selectors.runner(::Type{Builder.RenderDocument}, doc::Documenter.Docume
         * "] -- terminating build before rendering.")
     else
         @info "RenderDocument: rendering document."
-        Documenter.render(doc)
+        @time_basic doc "RenderDocument: rendering document." Documenter.render(doc)
     end
 end
 

src/documents.jl

@@ -298,6 +298,37 @@ Returns the first 5 characters of the current Git commit hash of the remote.
 """
 shortcommit(remoteref::RemoteRepository) = (length(remoteref.commit) > 5) ? remoteref.commit[1:5] : remoteref.commit
 
+@enum TimerStyle NoTimings BasicTimings FullTimings
+
+struct TimingContext
+    style::TimerStyle
+    timer::TimerOutputs.TimerOutput
+end
+
+TimingContext(style) = TimingContext(style, TimerOutputs.TimerOutput())
+
+macro time_level(level, doc, name, expr)
+    quote
+        if $(esc(doc)).user.timingcontext.style < $(esc(level))
+            TimerOutputs.disable_timer!($(esc(doc)).user.timingcontext.timer)
+        end
+        TimerOutputs.@timeit $(esc(doc)).user.timingcontext.timer $(esc(name)) $(esc(expr))
+        TimerOutputs.enable_timer!($(esc(doc)).user.timingcontext.timer)
+    end
+end
+
+macro time_basic(doc, name, expr)
+    quote
+        @time_level BasicTimings $(esc(doc)) $(esc(name)) $(esc(expr))
+    end
+end
+
+macro time_full(doc, name, expr)
+    quote
+        @time_level FullTimings $(esc(doc)) $(esc(name)) $(esc(expr))
+    end
+end
+
 """
 User-specified values used to control the generation process.
 """
@@ -340,6 +371,7 @@ struct User
     version :: String # version string used in the version selector by default
     highlightsig::Bool  # assume leading unlabeled code blocks in docstrings to be Julia.
     draft :: Bool
+    timingcontext :: TimingContext
 end
 
 """
@@ -400,6 +432,7 @@ function Document(;
         version :: AbstractString    = "",
         highlightsig::Bool           = true,
         draft::Bool                  = false,
+        timings                      = NoTimings,
         others...
     )
 
@@ -463,6 +496,7 @@ function Document(;
         version,
         highlightsig,
         draft,
+        TimingContext(timings),
     )
     internal = Internal(
         assetsdir(),