Faster load times

[mykelk]

It would be great if something could be done to speed up the load time.

In Julia 1.2.0:

julia> @time using PGFPlots
  8.497299 seconds (10.54 M allocations: 588.456 MiB, 4.25% gc time)

In Julia 1.3.1:

julia> @time using PGFPlots
 11.190039 seconds (15.89 M allocations: 835.859 MiB, 2.29% gc time)

It could be that we just have to wait for improvements in the Julia compilation engine and that there is not much we can do right now.

[mirkobunse]

When I tried timing the loading of PGFPlots myself, I observed some variation in the output of @time.

The following script computes the mean values of running @time using PGFPlots several times. It might prove useful for anyone who approaches the problem.

using StatsBase: mean

function profileOnce(trialInfo::String)
    output = read(`julia-1.3 --project=. -e "@time using PGFPlots"`, String)
    print(trialInfo, output)
    return output
end

function profile(n_trials::Int)
    outputs = profileOnce.(map(i -> "Trial $i/$n_trials:", 0:n_trials))
    data = hcat(map(
        x -> parse.(Float64, [x[i] for i in 1:4]),
        match.(
            r" (\d+.\d+) seconds \((\d+.\d+) M allocations: (\d+.\d+) GiB, (\d+.\d+)% gc time\)",
            outputs[2:end]
        )
    )...)' # parse all outputs into a Matrix{Float64} with shape (n_trials, 4)
    p = mean(data, dims=1) # profiling results
    println(
        "Mean @time (ignoring the first output due to possibly required pre-compilation):\n",
        " $(p[1]) seconds ($(p[2]) M allocations: $(p[3]) GiB, $(p[4])% gc time)"
    )
end

profile(3)

It's output on my machine:

Trial 0/3: 21.513392 seconds (36.36 M allocations: 1.844 GiB, 3.54% gc time)
Trial 1/3: 19.718410 seconds (36.36 M allocations: 1.844 GiB, 3.58% gc time)
Trial 2/3: 19.167825 seconds (36.36 M allocations: 1.844 GiB, 3.59% gc time)
Trial 3/3: 19.321575 seconds (36.36 M allocations: 1.844 GiB, 3.52% gc time)
Mean @time (ignoring the first output due to possibly required pre-compilation):
 19.40260333333333 seconds (36.36 M allocations: 1.8439999999999999 GiB, 3.563333333333333% gc time)

[mykelk]

Wow, that's a very long time.

[mirkobunse]

I have extended the above script to profile the load times of all dependencies. Here's the output, clearly dominated by TikzPictures.jl:

julia> profileDependencies()
[ Info: Mean @time using ColorSchemes: 1.477735 seconds
[ Info: Mean @time using DataFrames: 0.824797 seconds
[ Info: Mean @time using DelimitedFiles: 0.00050925 seconds
[ Info: Mean @time using Discretizers: 2.1551690000000003 seconds
[ Info: Mean @time using Distributed: 0.000534 seconds
[ Info: Mean @time using Printf: 0.0005235 seconds
[ Info: Mean @time using Requires: 0.14099450000000002 seconds
[ Info: Mean @time using StatsBase: 0.40059525 seconds
[ Info: Mean @time using TikzPictures: 9.1159525 seconds

These loading times add up to 14.1 seconds.

I do not know how the load time of a dependency precisely relates to the load time of a dependent package. For instance, lazy-loading DataFrames.jl already reduced the load time of PGFPlots.jl by 3sec, while loading DataFrames.jl itself is just 0.8sec.

Still, it might be valuable to check whether the load time of TikzPictures.jl can be reduced in any way, and how this reduction translates to the load time of PGFPlots.jl.

[mirkobunse]

I ran the same script on the dependencies of TikzPictures.jl.

...Aaand here's the bad boy:

julia> profileDependencies()
[ Info: Mean @time using LaTeXStrings: 0.0057083333333333335 seconds
[ Info: Mean @time using Poppler_jll: 8.098072 seconds

I wonder if there's any way to fix this. Poppler_jll is auto-generated by BinaryBuilder.jl.

[mykelk]

Wow, this is very helpful information. In Julia 1.5 on my old laptop, Poppler loads in under 4 seconds. That's still too long. We added Poppler to handle the conversion of pdfs to svg without having to rely on the binary pdf2svg:
JuliaTeX/TikzPictures.jl#55

[mirkobunse]

Wow, I just reverted this PR locally, and bam:

julia> profile()
[ Info: Mean @time using TikzPictures: 0.04385566666666666 seconds

Since I have pdf2svg installed, also the tests succeed.

[mykelk]

Whoa. Can we load poppler conditionally if we try to compile and it is discovered that pdf2svg doesn't exist?

[mirkobunse]

Long loading times seem to be a general problem with *_jll packages. However, the Julia developers are pretty involved in solving the underlying issues: JuliaPackaging/Yggdrasil#1050

On Julia-1.5, things are already much faster than on earlier versions:

julia-1.5 -e "@time using PGFPlots"
 10.471151 seconds (15.09 M allocations: 878.355 MiB, 2.75% gc time)
julia-1.5 -e "@time using Poppler_jll"
  2.266951 seconds (2.15 M allocations: 134.659 MiB, 0.70% gc time)

For comparison: PGFPlots took 16 seconds on Julia-1.3, Poppler took 8 seconds there (see above).

It might be possible to set up a MinimalPoppler_jll which only offers pdftocairo and omits the other functionality that slows down loading Poppler_jll. However, I am completely unexperienced with this stuff. Poppler_jll is maintained in the Yggdrasil repository.

[PallHaraldsson]

The JLL issue has been fixed (I'm not sure if the JLLs in this case have been regenerated too, but have for Gtk and it's much faster since minutes ago).

On my 4 days old Julia 16 master 5.54 seconds, and:

$ ./julia -O0 --compile=min --startup-file=no -q
julia> @time using PGFPlots
  4.645271 seconds (6.10 M allocations: 421.307 MiB, 2.68% gc time, 0.87% compilation time)

so it could possibly be even faster, just as I know Gtk is faster still (under a sec) than on my older master.

Also but 0.93 sec. and:

$ ./julia -O0 --compile=min --startup-file=no -q
julia> @time using TikzPictures
  0.373776 seconds (429.32 k allocations: 28.674 MiB, 10.88% compilation time)

[mykelk]

On my Julia 1.9.0 on Windows, I have 3.9 s for PGFPlots.jl, 2.9 s for Plots.jl, and 0.4 s for Poppler_jll.

[PallHaraldsson]

On my 1.9.0, apparently slower machine, I get:

julia> @time using PGFPlots
  4.706104 seconds (4.78 M allocations: 298.536 MiB, 6.13% gc time, 5.66% compilation time: 9% of which was recompilation)

While for:

julia> @time using Plots
  3.025017 seconds (3.19 M allocations: 178.997 MiB, 7.25% gc time, 0.60% compilation time)

Not much lower "compilation time" and also no "recompilation". And this is the culprit:

151.3 ms  ColorVectorSpace 16.29% compilation time (100% recompilation)

Or actually your largest single culprit (or its dependencies) is:

julia> @time using Images
  4.382229 seconds (4.49 M allocations: 282.911 MiB, 5.74% gc time, 5.25% compilation time: 15% of which was recompilation)

It seems it might be very important to this package (or not, since not a dependency of Plots.jl). I'm not sure, but could it be made an optional dependency?

The package has an enormous Indirect Dependencies (150), thereof Packages (86) and Binary Artifacts (38), and none of those are a major problem:

      6.1 ms  Fontconfig_jll 86.84% compilation time
      5.3 ms  Poppler_jll
      4.9 ms  OpenSpecFun_jll 88.00% compilation time
...

OffsetArrays (why is it needed? it's been suggested for Base) is required by ImageCore which is required by your dependencies ImageMagick and Images.

591.6 ms  ImageCore
528.0 ms  StaticArrays
403.7 ms  Rotations
355.3 ms  JLD2 28.30% compilation time
130.1 ms  FFTW
179.6 ms  Colors
106.0 ms  ColorTypes
 76.3 ms  DataStructures
 67.1 ms  TikzPictures 29.99% compilation time
 57.4 ms  FixedPointNumbers
 54.0 ms  OffsetArrays
 15.7 ms  CatIndices

  3.4 ms  StaticArraysCore (maybe only needed?)
528.0 ms  StaticArrays

julia> @time_imports using PGFPlots
      1.0 ms  Statistics
     57.4 ms  FixedPointNumbers
      0.3 ms  Reexport
    106.0 ms  ColorTypes
    179.6 ms  Colors
      3.4 ms  StaticArraysCore
    528.0 ms  StaticArrays
      1.3 ms  Contour
      0.3 ms  Requires
      0.9 ms  DataAPI
      0.2 ms  Compat
      0.2 ms  Compat → CompatLinearAlgebraExt
      9.8 ms  OrderedCollections
     76.3 ms  DataStructures
      0.5 ms  SortingAlgorithms
     12.5 ms  Missings
      1.2 ms  DocStringExtensions
      4.2 ms  IrrationalConstants
      0.4 ms  LogExpFunctions
      0.3 ms  StatsAPI
     21.0 ms  StatsBase
      0.3 ms  OpenLibm_jll
     14.4 ms  Preferences
      0.4 ms  JLLWrappers
      4.9 ms  OpenSpecFun_jll 88.00% compilation time
     14.4 ms  SpecialFunctions
      1.7 ms  Discretizers
      0.3 ms  TensorCore
    151.3 ms  ColorVectorSpace 16.29% compilation time (100% recompilation)
      7.9 ms  ColorSchemes
      0.3 ms  Adapt
      0.3 ms  Adapt → AdaptStaticArraysExt
     54.0 ms  OffsetArrays
      2.1 ms  PaddedViews
      3.1 ms  MappedArrays
      2.6 ms  StackViews
      0.8 ms  MosaicViews
      0.3 ms  NaNMath
      0.9 ms  Graphics
      5.2 ms  AbstractFFTs
    591.6 ms  ImageCore
     29.3 ms  ImageBase
    139.7 ms  FileIO
      4.7 ms  IndirectArrays
      7.5 ms  CoordinateTransformations
      0.2 ms  RealDot
      2.6 ms  Quaternions
    403.7 ms  Rotations
      4.6 ms  WoodburyMatrices
      6.3 ms  Ratios
      1.4 ms  Ratios → RatiosFixedPointNumbersExt
      0.3 ms  AxisAlgorithms
     40.3 ms  ChainRulesCore
      0.6 ms  LogExpFunctions → LogExpFunctionsChainRulesCoreExt
      0.8 ms  SpecialFunctions → SpecialFunctionsChainRulesCoreExt
      0.2 ms  AbstractFFTs → AbstractFFTsChainRulesCoreExt
     50.4 ms  Interpolations
      4.5 ms  ImageTransformations
     12.6 ms  MacroTools
      2.7 ms  SimpleTraits
      7.3 ms  RangeArrays
      0.2 ms  SuiteSparse
      2.9 ms  ArrayInterface
      0.4 ms  ArrayInterface → ArrayInterfaceStaticArraysCoreExt
      0.2 ms  IfElse
     50.4 ms  Static
      0.3 ms  SnoopPrecompile
     14.3 ms  StaticArrayInterface
      1.7 ms  StaticArrayInterface → StaticArrayInterfaceStaticArraysExt
      1.2 ms  StaticArrayInterface → StaticArrayInterfaceOffsetArraysExt
      0.6 ms  EllipsisNotation
     46.6 ms  IntervalSets
     50.5 ms  IterTools
     32.0 ms  AxisArrays
      8.9 ms  ImageAxes
     39.0 ms  ImageMetadata
      1.1 ms  FFTW_jll
    130.1 ms  FFTW
      0.3 ms  CustomUnitRanges
     16.6 ms  FFTViews
      4.2 ms  ComputationalResources
      8.0 ms  TiledIteration
     15.7 ms  CatIndices
    378.7 ms  ImageFiltering
     82.4 ms  ImageMorphology 84.13% compilation time
      5.4 ms  Distances
      3.0 ms  ImageDistances
      0.2 ms  UnPack
      0.4 ms  Parameters
     11.3 ms  ImageContrastAdjustment
      2.0 ms  LazyModules
      0.3 ms  PrecompileTools
    247.8 ms  ImageQualityIndexes
      3.8 ms  IntegralArrays
      5.4 ms  RegionTrees
     33.9 ms  NearestNeighbors
      6.4 ms  Clustering
      4.5 ms  ArnoldiMethod
      0.9 ms  Inflate
     45.5 ms  Graphs
      4.2 ms  TranscodingStreams
    355.3 ms  JLD2 28.30% compilation time
      6.5 ms  MetaGraphs
      8.9 ms  SimpleWeightedGraphs
      1.8 ms  ImageSegmentation
      1.9 ms  ImageShow
      7.3 ms  Images
     55.9 ms  Parsers
     15.0 ms  JSON
      0.4 ms  ColorBrewer
      0.9 ms  DelimitedFiles
      0.9 ms  LaTeXStrings
      0.5 ms  Bzip2_jll
      0.2 ms  Zlib_jll
      0.4 ms  FreeType2_jll
      0.4 ms  Libuuid_jll
      0.4 ms  Expat_jll
      6.1 ms  Fontconfig_jll 86.84% compilation time
      0.5 ms  Graphite2_jll
      0.5 ms  Libiconv_jll
      0.4 ms  Libffi_jll
      0.7 ms  XML2_jll
      0.5 ms  Gettext_jll
      0.2 ms  PCRE2_jll
      0.6 ms  Libmount_jll
      1.6 ms  Glib_jll
      0.5 ms  Pixman_jll
      0.5 ms  libpng_jll
      0.4 ms  Libgpg_error_jll
      0.5 ms  Libgcrypt_jll
      0.8 ms  XSLT_jll
      0.4 ms  Xorg_libXau_jll
      0.4 ms  Xorg_libXdmcp_jll
      0.3 ms  Xorg_libpthread_stubs_jll
      3.5 ms  Xorg_libxcb_jll
      0.3 ms  Xorg_xtrans_jll
      0.7 ms  Xorg_libX11_jll
      0.6 ms  Xorg_libXext_jll
      0.5 ms  Xorg_libXrender_jll
      0.4 ms  LZO_jll
      1.8 ms  Cairo_jll
      1.1 ms  HarfBuzz_jll
      6.6 ms  ICU_jll
      1.0 ms  HarfBuzz_ICU_jll
      0.9 ms  OpenSSL_jll
      0.5 ms  tectonic_jll
      0.8 ms  JpegTurbo_jll
      0.5 ms  LERC_jll
      0.5 ms  Zstd_jll
      1.2 ms  Libtiff_jll
      0.6 ms  LittleCMS_jll
      0.6 ms  OpenJpeg_jll
      5.3 ms  Poppler_jll
     67.1 ms  TikzPictures 29.99% compilation time
      7.7 ms  PGFPlots

[mykelk]

Images.jl is used for PGFPlots.Image and PGFPlots.Histogram2. I'm perfectly fine with it being loaded on the fly since many users don't make Image and Histogram2 plots.

[mykelk]

I also just removed the ImageMagick.jl dependency since it is captured by Images.jl.