Precompile times seem long

[jkrumbiegel]

This is admittedly a low-effort issue as I don't use TiffImages and have not tested it locally, but I noticed today that this package needs a sizable chunk of CI time of AlgebraOfGraphics.jl for precompilation. Here's a couple of entries from the log for comparison:

147103.2 ms  ✓ TiffImages
130059.3 ms  ✓ Makie
101776.8 ms  ✓ DataFrames
 14808.4 ms  ✓ StaticArrays
 40276.5 ms  ✓ Parsers
 43800.0 ms  ✓ HTTP

It surprises me that the package needs more precompilation time than Makie :) Maybe something could be optimized there given that this package appears as a dep in a few image-related packages?

[tlnagy]

Honestly, I've noticed this recently as well. The relative precompilation times have exploded. I don't have the bandwidth to track this down, but it would be nice to get it under control. We really shouldn't be longer than Makie. @chrstphrbrns any thoughts?

[chrstphrbrns]

What does the "precompilation helper" code do? When I remove it, precompilation drops from 40s to 5s

[tlnagy]

It's meant to speed up Time to First X, which in the case of TiffImages is the time to load the first image. Julia has to JIT the code the first time it's run and the "precompilation helper" code is meant to shift that to precompile time. Does the initial cold load time slow down if you remove it?

[chrstphrbrns]

For one particular image, load goes from 3s to 4s without the helper code

[jaakkor2]

I measured precompilation, using, and TTFX times for TiffImages v0.10.2, v0.11.3, and "dev" that is v0.11.3 without precompilation helper https://github.com/tlnagy/TiffImages.jl/blob/master/src/TiffImages.jl#L43-L59. Julia versions v1.8.5, v1.9.4, v1.10.8, v1.11.3.

Format of results is

@time using TiffImages # .julia/compiled/TiffImages removed
@time using TiffImages
@time (using TiffImages; TiffImages.save("foo.tiff", rand(TiffImages.ColorTypes.RGB{TiffImages.ColorTypes.N0f16},(320,200))); TiffImages.load("foo.tiff"))
Julia version, TiffIImages version, size of .julia/compiled/TiffImages

Higher the Julia version number, bigger the size of compiled files on disk. Julia v1.10.8 seems fastest. using time is faster without precompilation helper, but TTFX is slower.

I would prefer fast precompilation times for TiffImages as I rarely encounter the format, but I do see often the precompilation of TiffImages spinning and spinning on the screen.

 27.328625 seconds (3.84 M allocations: 264.829 MiB, 0.26% gc time, 0.10% compilation time: 4% of which was recompilation)
  1.230845 seconds (3.83 M allocations: 263.855 MiB, 5.63% gc time, 1.53% compilation time: 5% of which was recompilation)
  2.869972 seconds (6.79 M allocations: 407.466 MiB, 8.62% gc time, 51.57% compilation time: 0% of which was recompilation)
Julia v1.8, TiffImages v0.10, 14.98 MB
---
 38.849344 seconds (1.24 M allocations: 83.536 MiB, 0.10% gc time, 0.09% compilation time)
  0.864809 seconds (1.21 M allocations: 81.424 MiB, 0.37% compilation time)
  1.333654 seconds (1.95 M allocations: 130.817 MiB, 14.60% gc time, 24.31% compilation time)
Julia v1.9, TiffImages v0.10, 38.15 MB
---
 33.458359 seconds (896.02 k allocations: 65.380 MiB, 0.15% gc time, 0.38% compilation time)
  0.808882 seconds (800.73 k allocations: 58.471 MiB, 6.40% gc time, 2.62% compilation time)
  1.192662 seconds (1.42 M allocations: 99.279 MiB, 18.84% gc time, 26.65% compilation time)
Julia v1.10, TiffImages v0.10, 54.41 MB
---
 39.660573 seconds (1.96 M allocations: 125.584 MiB, 0.19% gc time, 0.40% compilation time)
  1.185974 seconds (1.23 M allocations: 77.427 MiB, 6.84% gc time, 1.41% compilation time)
  1.598249 seconds (1.84 M allocations: 108.253 MiB, 15.79% gc time, 16.72% compilation time)
Julia v1.11, TiffImages v0.10, 64.39 MB
---
 27.386197 seconds (3.88 M allocations: 267.671 MiB, 0.28% gc time, 0.10% compilation time: 4% of which was recompilation)
  1.256226 seconds (3.87 M allocations: 266.698 MiB, 5.75% gc time, 1.46% compilation time: 6% of which was recompilation)
  3.009492 seconds (7.24 M allocations: 432.162 MiB, 8.37% gc time, 52.71% compilation time: 0% of which was recompilation)
Julia v1.8, TiffImages v0.11, 14.89 MB
---
 42.138981 seconds (1.26 M allocations: 85.218 MiB, 0.11% gc time, 0.09% compilation time)
  0.933436 seconds (1.24 M allocations: 83.106 MiB, 0.36% compilation time)
  1.425492 seconds (2.07 M allocations: 139.159 MiB, 14.18% gc time, 25.95% compilation time)
Julia v1.9, TiffImages v0.11, 40.47 MB
---
 34.439771 seconds (912.66 k allocations: 66.463 MiB, 0.17% gc time, 0.32% compilation time)
  0.757143 seconds (817.37 k allocations: 59.551 MiB, 7.33% gc time, 2.52% compilation time)
  1.196244 seconds (1.51 M allocations: 105.777 MiB, 20.09% gc time, 26.73% compilation time)
Julia v1.10, TiffImages v0.11, 56.83 MB
---
 42.264662 seconds (2.03 M allocations: 129.723 MiB, 0.22% gc time, 0.37% compilation time)
  1.249766 seconds (1.28 M allocations: 80.491 MiB, 7.06% gc time, 1.30% compilation time)
  1.703554 seconds (2.04 M allocations: 119.128 MiB, 16.98% gc time, 18.15% compilation time)
Julia v1.11, TiffImages v0.11, 68.40 MB
---
  2.146943 seconds (1.53 M allocations: 105.019 MiB, 0.28% gc time, 1.23% compilation time: 4% of which was recompilation)
  0.629975 seconds (1.51 M allocations: 104.048 MiB, 0.87% gc time, 2.93% compilation time: 5% of which was recompilation)
  4.019207 seconds (24.38 M allocations: 1.270 GiB, 11.09% gc time, 81.98% compilation time: 0% of which was recompilation)
Julia v1.8, TiffImages dev, 0.46 MB
---
  2.216488 seconds (639.65 k allocations: 45.040 MiB, 2.02% gc time, 1.71% compilation time)
  0.507647 seconds (614.47 k allocations: 42.919 MiB, 0.64% compilation time)
  3.834097 seconds (13.43 M allocations: 858.529 MiB, 8.16% gc time, 83.13% compilation time)
Julia v1.9, TiffImages dev, 1.02 MB
---
  2.110594 seconds (473.62 k allocations: 37.711 MiB, 5.32% compilation time)
  0.294744 seconds (378.33 k allocations: 30.792 MiB, 6.52% compilation time)
  3.747269 seconds (11.63 M allocations: 790.534 MiB, 9.92% gc time, 89.23% compilation time)
Julia v1.10, TiffImages dev, 1.03 MB
---
  3.709052 seconds (1.16 M allocations: 78.479 MiB, 0.70% gc time, 4.46% compilation time)
  0.719617 seconds (675.18 k allocations: 44.843 MiB, 7.61% gc time, 2.31% compilation time)
  4.638373 seconds (22.51 M allocations: 1.105 GiB, 7.80% gc time, 81.52% compilation time)
Julia v1.11, TiffImages dev, 1.50 MB

[tlnagy]

Thanks @jaakkor2 for the thorough testing. Yeah, it's unfortunate, but a tripling in time to first image (2.7x slower in your dev version vs master using Julia 1.11) is a hard thing to accept. Generally, precompilation only really hits folks whenever they install TiffImages while TTFI hits them every time they load Julia.

I could be open to reducing the number of branches that we precompile and only prepare for the simple Gray+N0f8, N0f16 images and we can let the rest be JITed when needed.

[jkrumbiegel]

I've written out timings of the four things being done in that precompilation helper, for each combination. You can read this plot from left to right, top to bottom in the actual order things ran in. (I reordered the loop so size is the outer variable). This was done on 1.12.

df = Any[["sz", "c", "t", "kind", "time"]]

## Precompilation helper
mktemp() do fpath, _
    for sz in ((2, 2), (2, 2, 2))
        for c in Any[Gray, GrayA, RGB, RGBA]
            for t in Any[N0f8, N0f16, Float32, Float64]
                @info "Group" t c sz
                e1 = @elapsed TiffImages.save(fpath, rand(c{t}, sz))
                e2 = @elapsed TiffImages.load(fpath)
                e3 = @elapsed let img = TiffImages.load(fpath; mmap=true) end
                e4 = @elapsed let img = TiffImages.load(fpath; lazyio=true) end
                for (e, kind) in zip([e1, e2, e3, e3], ["save", "load", "load mmap", "load lazyio"])
                    push!(df, [string(sz), string(nameof(c)), string(t), kind, e])
                end
                # On Windows, trying to delete a file before garbage-collecting
                # its corresponding mmapped-array results in an error.
                # Here, this manifests as an error in precompiling the package,
                # which is quite a serious problem.
                # Thus try hard to make sure we free all the temporaries.
                Sys.iswindows() && GC.gc()
            end
        end
    end
end

open("precompiles.csv", "w") do io
    for row in df
        println(io, join(repr.(row), ","))
    end
end

using CSV, DataFrames, AlgebraOfGraphics, CairoMakie


df = CSV.read("/Users/krumbiegel/.julia/dev/TiffImages/precompiles.csv", DataFrame)

df.t .= replace.(df.t, "FixedPointNumbers." => "")

data(df) *
    mapping(:t => presorted, :time, dodge = :kind => presorted, color = :kind => presorted, row = :sz => presorted, col = :c => presorted) *
    visual(BarPlot) |> draw(; axis = (; xticklabelrotation = pi/4))

df2 = combine(groupby(df, :kind), :time => sum)

data(df2) * mapping(:kind => presorted, :time_sum => "time", color = :kind => presorted) * visual(BarPlot) |> draw

And these are the cumulative timings on my machine for the four categories

So loading and saving each contribute about the same amount of overall time but are distributed differently.

The very first load and save are each about 2-3x the duration of the others. So my conclusion from this is that it should be enough to cache one of each to save the bulk of the first latency. Plus, PrecompileTools could be tried to cache more of the non-package code.

I personally would remove all but one save because saving is at the end of an analysis and this is where perceived latency is less critical. For the loads, I would probably also just keep one, but if more should be kept there's no good cutoff except taking all. Unless you have ideas about which of these formats are most common.

[tlnagy]

The very first load and save are each about 2-3x the duration of the others. So my conclusion from this is that it should be enough to cache one of each to save the bulk of the first latency. Plus, PrecompileTools could be tried to cache more of the non-package code.

I personally would remove all but one save because saving is at the end of an analysis and this is where perceived latency is less critical. For the loads, I would probably also just keep one, but if more should be kept there's no good cutoff except taking all. Unless you have ideas about which of these formats are most common.

This great analysis and I agree re your point on saving. I would be open to removing the save code from the precompilation. I would also only precompile Gray{all formats} and both sizes and RGB{all formats} and both sizes. That should cut the load precompilation in half and the saving precompilation to zero.

[tlnagy]

Fixed by #185

[jkrumbiegel]

Note that precompilation on master CI still takes 60 seconds, which is still a lot for a package like this that gets pulled in everywhere. So "fixed" is relative, but at least it's better than before.