Extremely long runtimes of ExpandTemplates with Julia > 1.1 #1261

michakraus · 2020-03-16T13:59:59Z

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.

The text was updated successfully, but these errors were encountered:

michakraus · 2020-03-16T14:38:55Z

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 · 2020-03-19T15:11:55Z

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 · 2020-04-16T18:06:42Z

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 · 2020-04-16T18:30:43Z

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 · 2020-04-17T04:21:07Z

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 · 2020-09-01T00:57:36Z

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 · 2020-09-01T15:17:48Z

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

What was the difference between those runs?

epatters · 2020-09-01T20:51:41Z

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 (AlgebraicJulia/Catlab.jl#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 · 2020-09-01T22:13:54Z

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 · 2020-09-01T22:20:54Z

Ah ok, thanks for explaining.

fredrikekre · 2020-09-01T22:22:29Z

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 · 2020-09-01T23:44:30Z

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 · 2021-04-19T14:23:51Z

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

KristofferC · 2021-04-20T11:44:29Z

@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 · 2021-04-20T15:29:02Z

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 · 2021-04-20T15:35:24Z

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

Documenter.jl/src/Expanders.jl

Lines 37 to 45 in 97f1a9f

    
           for src in Iterators.flatten([priority_pages, normal_pages]) 
        
               page = doc.blueprint.pages[src] 
        
               @debug "Running ExpanderPipeline on $src" 
        
               empty!(page.globals.meta) 
        
               for element in page.elements 
        
                   Selectors.dispatch(ExpanderPipeline, element, page, doc) 
        
               end 
        
               pagecheck(page) 
        
           end

and for more fine-grained timings over

Documenter.jl/src/Expanders.jl

Lines 41 to 43 in 97f1a9f

    
           for element in page.elements 
        
               Selectors.dispatch(ExpanderPipeline, element, page, doc) 
        
           end

AnHeuermann · 2022-08-22T12:44:39Z

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 · 2023-11-29T19:00:05Z

If you want to measure it further you can time over

Documenter.jl/src/Expanders.jl

Lines 37 to 45 in 97f1a9f

for src in Iterators.flatten([priority_pages, normal_pages])

page = doc.blueprint.pages[src]

@debug "Running ExpanderPipeline on $src"

empty!(page.globals.meta)

for element in page.elements

Selectors.dispatch(ExpanderPipeline, element, page, doc)

end

pagecheck(page)

end

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?

epatters mentioned this issue Sep 1, 2020

Docs now take a very long time to build AlgebraicJulia/Catlab.jl#247

Closed

This was referenced Oct 17, 2020

Heavy slowdown in ExpandTemplates due to subtypes function #1438

Closed

subtypes function runs very slowly JuliaLang/julia#38079

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Extremely long runtimes of ExpandTemplates with Julia > 1.1 #1261

Extremely long runtimes of ExpandTemplates with Julia > 1.1 #1261

michakraus commented Mar 16, 2020 •

edited

Loading

michakraus commented Mar 16, 2020

michakraus commented Mar 19, 2020 •

edited

Loading

ziotom78 commented Apr 16, 2020

michakraus commented Apr 16, 2020

ziotom78 commented Apr 17, 2020

epatters commented Sep 1, 2020 •

edited

Loading

fredrikekre commented Sep 1, 2020

epatters commented Sep 1, 2020

michakraus commented Sep 1, 2020 •

edited

Loading

epatters commented Sep 1, 2020

fredrikekre commented Sep 1, 2020

epatters commented Sep 1, 2020 •

edited

Loading

charleskawczynski commented Apr 19, 2021

KristofferC commented Apr 20, 2021 •

edited

Loading

charleskawczynski commented Apr 20, 2021

KristofferC commented Apr 20, 2021 •

edited

Loading

AnHeuermann commented Aug 22, 2022

milankl commented Nov 29, 2023

Extremely long runtimes of ExpandTemplates with Julia > 1.1 #1261

Extremely long runtimes of ExpandTemplates with Julia > 1.1 #1261

Comments

michakraus commented Mar 16, 2020 • edited Loading

michakraus commented Mar 16, 2020

michakraus commented Mar 19, 2020 • edited Loading

ziotom78 commented Apr 16, 2020

michakraus commented Apr 16, 2020

ziotom78 commented Apr 17, 2020

epatters commented Sep 1, 2020 • edited Loading

fredrikekre commented Sep 1, 2020

epatters commented Sep 1, 2020

michakraus commented Sep 1, 2020 • edited Loading

epatters commented Sep 1, 2020

fredrikekre commented Sep 1, 2020

epatters commented Sep 1, 2020 • edited Loading

charleskawczynski commented Apr 19, 2021

KristofferC commented Apr 20, 2021 • edited Loading

charleskawczynski commented Apr 20, 2021

KristofferC commented Apr 20, 2021 • edited Loading

AnHeuermann commented Aug 22, 2022

milankl commented Nov 29, 2023

michakraus commented Mar 16, 2020 •

edited

Loading

michakraus commented Mar 19, 2020 •

edited

Loading

epatters commented Sep 1, 2020 •

edited

Loading

michakraus commented Sep 1, 2020 •

edited

Loading

epatters commented Sep 1, 2020 •

edited

Loading

KristofferC commented Apr 20, 2021 •

edited

Loading

KristofferC commented Apr 20, 2021 •

edited

Loading