Skip to content

Commit

Permalink
start docs section about loading/precomp/ttfx time
Browse files Browse the repository at this point in the history
  • Loading branch information
IanButterworth committed Sep 7, 2024
1 parent 8cae8d1 commit 0c0fdf0
Showing 1 changed file with 110 additions and 0 deletions.
110 changes: 110 additions & 0 deletions doc/src/manual/performance-tips.md
Original file line number Diff line number Diff line change
Expand Up @@ -1394,6 +1394,116 @@ Prominent examples include [MKL.jl](https://github.com/JuliaLinearAlgebra/MKL.jl
These are external packages, so we will not discuss them in detail here.
Please refer to their respective documentations (especially because they have different behaviors than OpenBLAS with respect to multithreading).

## Execution latency, loading and precompiling time

### Reducing time to first plot etc.

The first time a julia function is called it will be compiled. The [`@time`](@ref) macro family illustrates this.

```
julia> foo() = rand(2,2) * rand(2,2)
foo (generic function with 1 method)
julia> @time @eval foo();
0.252395 seconds (1.12 M allocations: 56.178 MiB, 2.93% gc time, 98.12% compilation time)
julia> @time @eval foo();
0.000156 seconds (63 allocations: 2.453 KiB)
```

Note that `@time @eval ...` form is explained in the [`@time`](@ref) documentation.

When developing a package, it can be helpful to cache this compilation in the package caches that are "precompiled"
during the `Pkg` installation process or before package load. To precompile package code effectively, it's recommended
to use [`PrecompileTools.jl`](https://julialang.github.io/PrecompileTools.jl/stable/) to run a "precompile workload" during
precompilation time that is representative of typical package usage, which will cache the native compiled code into the
package `pkgimage` cache, greatly reducing "time to first ..." (often referred to as TTFX) for such usage.


### Reducing package loading time

When keeping the time taken to load the package down is usually helpful.
General good practice for package developers includes:

1. Balancing the need to depending on packages for functionality vs. their load times, including stdlibs which on newer
julia versions may not be loaded already as stdlibs are no longer always included in the default sysimage.
2. Avoiding adding `__init__` functions to package modules unless unavoidable, especially those which might trigger a
lot of compilation, or just take a long time to execute.
3. Watch out for invalidations in the dependency tree during load that could be causing significant recompilation downstream.

The `InteractiveUtils` tool [`@time_imports`](@ref) can be useful in the REPL to review the above factors.

```julia-repl
julia> @time @time_imports using Plots
0.5 ms Printf
16.4 ms Dates
0.7 ms Statistics
┌ 23.8 ms SuiteSparse_jll.__init__() 86.11% compilation time (100% recompilation)
90.1 ms SuiteSparse_jll 91.57% compilation time (82% recompilation)
0.9 ms Serialization
┌ 39.8 ms SparseArrays.CHOLMOD.__init__() 99.47% compilation time (100% recompilation)
166.9 ms SparseArrays 23.74% compilation time (100% recompilation)
0.4 ms SparseArraysExt
0.5 ms TOML
8.0 ms Preferences
0.3 ms PrecompileTools
0.2 ms Reexport
... many deps omitted for example ...
1.4 ms Tar
┌ 73.8 ms p7zip_jll.__init__() 99.93% compilation time (100% recompilation)
79.4 ms p7zip_jll 92.91% compilation time (100% recompilation)
┌ 27.7 ms GR.GRPreferences.__init__() 99.77% compilation time (100% recompilation)
43.0 ms GR 64.26% compilation time (100% recompilation)
┌ 2.1 ms Plots.__init__() 91.80% compilation time (100% recompilation)
300.9 ms Plots 0.65% compilation time (100% recompilation)
1.795602 seconds (3.33 M allocations: 190.153 MiB, 7.91% gc time, 39.45% compilation time: 97% of which was recompilation)
```

Notice that in this example there are multiple packages loaded, some with `__init__()` functions, some of which cause
compilation of which some is recompilation.

This report gives a good opportunity to review whether the cost of dependency load time is worth the functionality it brings.
Also the `Pkg` utility `why` can be used to report why a an indirect dependency exists.

```
(CustomPackage) pkg> why FFMPEG_jll
Plots → FFMPEG → FFMPEG_jll
Plots → GR → GR_jll → FFMPEG_jll
```

or to see the indirect dependencies that a package brings in, you can `pkg> rm` the package, see the deps that are removed
from the manifest, then revert the change with `pkg> undo`.

If loading time is dominated by slow `__init__()` methods having compilation, one verbose way to identify what is being
compiled is to use the julia args `--trace-compile=stderr --trace-compile-timing` which will report a [`precompile`](@ref)
statement each time a method is compiled, along with how long compilation took. For instance, the full setup would be:

```
$ julia --startup-file=no --trace-compile=stderr --trace-compile-timing
julia> @time @time_imports using CustomPackage
...
```

Note the `--startup-file=no` which helps isolate the test from packages you may have in your `startup.jl`.

More analysis of the reasons for recompilation can be achieved with the
[`SnoopCompile`](https://github.com/timholy/SnoopCompile.jl) package.

### Reducing precompilation time

If package precompilation is taking a long time, one option is to set the following internal and then precompile.
```
julia> Base.PRECOMPILE_TRACE_COMPILE[] = "stderr"
pkg> precompile
```

This has the effect of setting `--trace-compile=stderr --trace-compile-timing` in the precompilation processes themselves,
so will show which methods are precompiled and how long they took to precompile.

There are also profiling options such as [using the external profiler Tracy to profile the precompilation process](@ref Profiling-package-precompilation-with-Tracy).


## Miscellaneous

Expand Down

0 comments on commit 0c0fdf0

Please sign in to comment.