Extremely long runtimes of ExpandTemplates with Julia > 1.1

[michakraus]

I found that generating documentation for my library GeometricIntegrators.jl went from tens of seconds with Julia v1.1 to about an hour with Julia v1.3.

The main reason seems to be the step ExpandTemplates: expanding markdown templates. Everything else still runs reasonably fast. I was able to isolate a few files in the library which are particularly problematic, but I cannot see any decisive differences to other files, which are processed much quicker. For one of these files the "ExpandTemplates" time rose from 1-2s to 75-80s going from Julia v1.1 to v1.3, changing nothing else.

It is kind of hard to provide a MWS as the problematic files depend on many other modules in the library. If someone wants to look into this, I could, however, provide a branch with a minimal doc setup for testing purposes. However, maybe this is a somewhat known problem and there is an immediate explanation.

I tested just now with Documenter v0.24.6 but this problem seems to have existed for some time. So far, I just used Julia v1.1 to generate documentation, but now I use Julia v1.3 features in the library, so this is not an option anymore.

Addendum: For most of the documentation I am using @autodocs, e.g., for the aforementioned file,

```@autodocs
Modules = [GeometricIntegrators.Integrators.Stochastic]
Pages   = ["src/integrators/stochastic/integrators_wirk.jl",]
```

but usually without the Pages argument.

[michakraus]

Update: It seems I could identify the reason: generated functions! The aforementioned file has two of them. A makedocs run for just this file takes 88s. If I comment those generated functions it only takes 16s.

[michakraus]

I refactored my code and got rid of all the @generated functions (something I had anyhow planned). Now the whole makedocs takes about 700s. Which is much faster than before (with the @generated functions) but still much longer than with Julia v1.1.

I @time'ed a makedocs() run on a subset of the documentation. There seems to be a tremedous difference in allocations between the Julia versions:

Julia v1.1: 16.840504 seconds (43.12 M allocations: 2.143 GiB, 6.10% gc time) Julia v1.2: 61.381548 seconds (104.21 M allocations: 14.739 GiB, 5.01% gc time) Julia v1.3: 67.072681 seconds (98.50 M allocations: 14.388 GiB, 4.50% gc time) Julia v1.4: 67.324340 seconds (100.25 M allocations: 14.436 GiB, 4.55% gc time)

Seems to be a warmup issue, for the second run of makedocs() I get:

Julia v1.1: 1.645262 seconds (299.69 k allocations: 59.378 MiB, 2.22% gc time) Julia v1.2: 1.690008 seconds (924.74 k allocations: 100.154 MiB, 2.81% gc time) Julia v1.3: 1.818764 seconds (354.95 k allocations: 65.776 MiB, 1.26% gc time) Julia v1.4: 1.725848 seconds (358.35 k allocations: 66.307 MiB, 1.16% gc time)

[ziotom78]

I am experiencing the same problem with Julia 1.4.0, although I do not have @generated functions in my code. The ExpandTemplates: expanding markdown templates was apparently stuck, and after ~15 minutes I pressed Ctrl-C, obtaining the following backtrace:

^C^CERROR: LoadError: InterruptException:
Stacktrace:
 [1] poptaskref(::Base.InvasiveLinkedListSynchronized{Task}) at ./task.jl:702
 [2] wait() at ./task.jl:709
 [3] uv_write(::Base.PipeEndpoint, ::Ptr{UInt8}, ::UInt64) at ./stream.jl:935
 [4] unsafe_write(::Base.PipeEndpoint, ::Ptr{UInt8}, ::UInt64) at ./stream.jl:1007
 [5] unsafe_write at ./io.jl:593 [inlined]
 [6] unsafe_write(::Base.PipeEndpoint, ::Base.RefValue{UInt8}, ::Int64) at ./io.jl:591
 [7] write at ./io.jl:594 [inlined]
 [8] write(::Base.PipeEndpoint, ::UInt8) at ./stream.jl:1045
 [9] write at ./io.jl:647 [inlined]
 [10] print at ./char.jl:229 [inlined]
 [11] println(::Base.PipeEndpoint) at ./coreio.jl:5
 [12] println() at ./coreio.jl:4
 [13] (::Documenter.Utilities.var"#16#17"{Documenter.Expanders.var"#14#17"{Documenter.Documents.Page,Module,Expr},Base.TTY,Base.TTY,Pipe,Array{UInt8,1}})() at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Utilities/Utilities.jl:572
 [14] with_logstate(::Documenter.Utilities.var"#16#17"{Documenter.Expanders.var"#14#17"{Documenter.Documents.Page,Module,Expr},Base.TTY,Base.TTY,Pipe,Array{UInt8,1}}, ::Base.CoreLogging.LogState) at ./logging.jl:398
 [15] with_logger(::Function, ::Logging.ConsoleLogger) at ./logging.jl:505
 [16] withoutput at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Utilities/Utilities.jl:561 [inlined]
 [17] runner(::Type{Documenter.Expanders.ExampleBlocks}, ::Markdown.Code, ::Documenter.Documents.Page, ::Documenter.Documents.Document) at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Expanders.jl:554
 [18] dispatch(::Type{Documenter.Expanders.ExpanderPipeline}, ::Markdown.Code, ::Vararg{Any,N} where N) at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Utilities/Selectors.jl:167
 [19] expand(::Documenter.Documents.Document) at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Expanders.jl:42
 [20] runner(::Type{Documenter.Builder.ExpandTemplates}, ::Documenter.Documents.Document) at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Builder.jl:214
 [21] dispatch(::Type{Documenter.Builder.DocumentPipeline}, ::Documenter.Documents.Document) at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Utilities/Selectors.jl:167
 [22] #2 at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Documenter.jl:237 [inlined]
 [23] cd(::Documenter.var"#2#3"{Documenter.Documents.Document}, ::String) at ./file.jl:104
 [24] #makedocs#1 at /home/tomasi/.julia/packages/Documenter/QQWIJ/src/Documenter.jl:236 [inlined]
 [25] top-level scope at /home/tomasi/Projects/julia/Stripeline.jl/docs/make.jl:9
 [26] include(::String) at ./client.jl:439
 [27] top-level scope at REPL[31]:1
 [28] eval(::Module, ::Any) at ./boot.jl:331
 [29] eval_user_input(::Any, ::REPL.REPLBackend) at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.4/REPL/src/REPL.jl:86
 [30] run_backend(::REPL.REPLBackend) at /home/tomasi/.julia/packages/Revise/Pcs5V/src/Revise.jl:1073
 [31] top-level scope at none:0
in expression starting at /home/tomasi/Projects/julia/Stripeline.jl/docs/make.jl:9

Redoing the test two more times, the backtrace was always the same: the process seems to hang at line 702 in task.jl. I searched in Julia's issues, and found #35441, which mentions possible deadlocks after a commit to the Julia repository done several months ago. I am not an expert of task.jl, so I do not know if that issue applies here; but the word «deadlock» is suggestive…

[michakraus]

In my cases, Documenter always finishes, but a run that takes one or two minutes with Julia v1.1 can take up to one or two hours on Julia v1.2 - v1.4.

[ziotom78]

After some debugging I realized there was a mistake in my part: because of a typo, the code in a @example block was printing a few thousands of lines to stdout, and this probably caused the freeze in my case.

I'm sorry for the spam!

[epatters]

I just started experiencing a similar problem with the ExpandTemplates step taking a very long time. The time for the docs build jumped from ~10 min to one hour, both running on Julia v1.5.

This may be related to @generated functions. I've been using @generated functions in Catlab.jl for a while, but a rewrite was just done on that code, resulting in a somewhat different usage.

[fredrikekre]

jumped from ~10 min to one hour, both running on Julia v1.5.

What was the difference between those runs?

[epatters]

Hi, thanks for asking. The short version is that, in a fairly complex PR, we changed the types behind a data structure based on @generated code. On our end we're currently trying to figure out whether we're doing something wrong (https://github.com/AlgebraicJulia/Catlab.jl/issues/247).

I thought I'd also post here because it sounds like someone else had a similar problem. @michakraus, if don't mind my asking, did you ever get any insight into what caused your slowdown, or was the problem simply resolved by your removing @generated code?

[michakraus]

The latter, unfortunately. I wasn't able to pin this down further. But indeed, refactoring our code, removing many of the generated functions, sped up the doc build quite dramatically. Not to what it was with Julia v1.1, but close enough.

[epatters]

Ah ok, thanks for explaining.

[fredrikekre]

It would be very useful if someone could push a branch with just a subset of the documentation that still shows the slow behavior, perhaps just a single page, with a few docstrings.

[epatters]

Thanks, I made a branch with a small subset of the docs. The build now takes 10 min, longer than the original full build used to take. What's even stranger is that the included docs are disjoint from the changes that seem to have caused the slowdown. (In particular, none of the @generated functions are being called, although the containing module is being loaded.) Based on my other experiments, I think it's the @example blocks that are running slowly.

[charleskawczynski]

We're also experiencing long expanding templates over at ClimateMachine.jl. It takes about 6 minutes for us.

[KristofferC]

@charleskawczynski, I instrumented Documenter a bit and the majority of time is spent in:

https://github.com/CliMA/ClimateMachine.jl/blob/master/docs/src/HowToGuides/Atmos/AtmosReferenceState.md

and

https://github.com/CliMA/ClimateMachine.jl/blob/master/docs/src/HowToGuides/Common/Thermodynamics.md

taking 112s and 55s respectively.

[charleskawczynski]

Hm, that leaves about 3 minutes. That's still pretty long, no?

Those files taking half the time makes sense, though. Thanks for looking into that.

[KristofferC]

On my machine, it was not really 6 minutes and those took the majority of that time.

If you want to measure it further you can time over

https://github.com/JuliaDocs/Documenter.jl/blob/97f1a9f663f63e66d4d4d13d2cdf200fa30c5dfc/src/Expanders.jl#L37-L45

and for more fine-grained timings over

https://github.com/JuliaDocs/Documenter.jl/blob/97f1a9f663f63e66d4d4d13d2cdf200fa30c5dfc/src/Expanders.jl#L41-L43

[AnHeuermann]

Hey. I may encountered a similar issue on a package I'm developing in Julia v1.7.2. It's not published yet, so I can't share it, though.

When I change the activated packages when calling make.jl it works.

Calling it like this will not finish (I canceled after 55 minutes)

julia --project=docs/ -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
julia --project=docs/ docs/make.jl

In this case my myPackage.jl get's added to docs/Project.toml.

But removing myPackage from docs/Project.toml and running

julia -e 'using Pkg; Pkg.add(name="Documenter", version="0.27"); Pkg.activate(pwd()); include("docs/make.jl")'

succeeds in around 1:45 minutes.

Also when remove all the @repl and @example blocks, ExpandTemplates is able to finish the compilation. But that won't help me with my documentation.

[milankl]

If you want to measure it further you can time over

https://github.com/JuliaDocs/Documenter.jl/blob/97f1a9f663f63e66d4d4d13d2cdf200fa30c5dfc/src/Expanders.jl#L37-L45

I was also facing insanely long times on ExpandTemplates (15min+) for something that used to take only seconds when doing locally. I just do include("docs/make.jl") repeatedly when writing the documentation, the first time it takes obviously longer because of compilation, but after that it used to be only seconds. I realised that I had accidentally made one of the @example blocks really expensive to calculate.

I was wondering whether the build info could just include some information of how long various pages took (following your timing suggestion @KristofferC). For example

julia> include("docs/make.jl")
[ Info: SetupBuildDirectory: setting up build directory.
[ Info: Doctest: running doctests.
[ Info: ExpandTemplates: expanding markdown templates.
[ Info: page1.md built in 2s.
[ Info: page2.md built in 240s.
[ Info: page3.md built in 3s.
...

That will probably help people to better identify what's going on during the documentation build?