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.

[PallHaraldsson]

[Off-topic, or seemingly not changing timing]
I see you removed DataFrames (not just ImageMagic which seems ok, and likely from [compat] too) from [compat], for a version, and I thought for master too (can't really see why it's not applied there). My understanding is that you want to have this like:

DataFrames = "0.21, 0.22, 1.0" # note, no need to add e.g. 1.6, or keep 1.5, since implied, however you want to keep those pre-1.0 versions (dropping the lines allows even older?)?

I.e. not (much) changed:

(@v1.9) pkg> add PGFPlots#master

julia> @time using PGFPlots
  4.656303 seconds (4.78 M allocations: 298.772 MiB, 6.17% gc time, 3.13% compilation time: 9% of which was recompilation)

thereof:

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

While this seems a bit faster, may have been lucky, and just testing difference in noise (also unclear you can force, -O0 optimization, i.e. it's possible, but I think only in the package, so for all users, not controllable by the user, so optional dependency still best bet):

$ julia -O0
julia> @time using Images
  4.269737 seconds (4.49 M allocations: 282.892 MiB, 5.88% gc time, 3.22% compilation time: 13% of which was recompilation)

[mykelk]

I'm looking at master and I still see the compat entries for DataFrames. I do want to limit it to version 1.5 because currently 1.6 fails (they are about to merge a fix, hopefully)---but for some reason the CI is still loading DataFrames 1.6 even though I think compat should be forcing it to 1.5. If you have thoughts on this or a solution, feel free to file a separate issue. Thanks!

[PallHaraldsson]

I managed much faster startup by, I guess (for now) braking some functionality, rather than delay loading it:

julia> @time using PGFPlots
  1.542727 seconds (1.79 M allocations: 115.021 MiB, 6.92% gc time, 8.10% compilation time: 21% of which was recompilation)

julia> x = [1,2,3];
julia> y = [2,4,1];

julia> plot(x, y)
TikzPictures.TikzPicture("\\begin{axis}\n\n\\addplot+ coordinates {\n  (1, 2)\n  (2, 4)\n  (3, 1)\n};\n\n\\end{axis}", "", "\\usepackage{pgfplots}\n\\pgfplotsset{compat=newest}\n\\pgfplotsset{every axis legend/.append style={%\ncells={anchor=west}}\n}\n\\usetikzlibrary{arrows}\n\\tikzset{>=stealth'}\n", "tikzpicture", "", "", true, true)

julia> print(tikzCode(x, y))
\begin{axis}

\addplot+ coordinates {
  (1, 2)
  (2, 4)
  (3, 1)
};

\end{axis}

I was expecting a plot as in the docs, for the plot command, though since I got no error I went further, and think this s to be expected.

I could make a (partial) PR/Draft. It's a trivial change so far. I don't even care that much about this exact package, don't use it, I just care about the (plotting) ecosystem in general, and investigating how startup time can be improved. I'm just using your package as a laboratory to test, and learn what the issues are.

[PallHaraldsson]

I believe I disabled Images.jl, why a got the time down so I'm still surprised to see:

  3.5 ms  StaticArraysCore
611.6 ms  StaticArrays

Those are not your direct dependencies, only indirect, and do you know where they might come from? I went through all your direct dependencies at juliahub.com, but missed seeing it. I believe most that use StaticArrays, need not, should rather use the much faster StaticArraysCore only, directly. I can't notify all, but maybe notifying Images would be of help, if I'm correct not needed there.

FYI: Looking up your package "PGFPlots.jl" doesn't find it, as with any with.jl (should be fixed there), and while "PGFPlots" finds it, it actually lists PGFPlotsX first. I would be curious why, and usually prefer alphabetical order, unless that one actually better... And it actually:

julia> @time using PGFPlotsX
  0.336557 seconds (255.51 k allocations: 17.898 MiB, 7.01% compilation time)

since:

It is similar in spirit to the package PGFPlots.jl but it tries to have a very close mapping to the PGFPlots API as well as minimize the number of dependencies. [..]

Features include:

[..]
Exporting to tex, pdf, svg, and png, file formats.

In your case svg seems to be the main point, is the other a superset of your functionality, just different API?

[mykelk]

PGFPlotsX was designed after PGFPlots. PGFPlotsX was designed to be a relatively thin wrapper around the pgfplots latex package. PGFPlots, however, provides more functionality such as creating Images and 2D histograms easily. The API, therefore, is pretty different. PGFPlots requires generating PNG image files, and relies upon Images.jl. I'm not sure whether Images.jl can get away with just using StaticArraysCore. There does not appear to be an issue filed there yet.