FileIO is a heavy dependency.

[KristofferC]

By default, Plots.jl takes about 40 seconds to compile, 18 seconds to start when already precompiled.

Commenting out

Plots.jl/src/output.jl

Lines 219 to 237 in 1ed7899

	if is_installed("FileIO")
	@eval import FileIO
	function _show(io::IO, ::MIME"image/png", plt::Plot)
	fn = tempname()
	# first save a pdf file
	pdf(plt, fn)
	# load that pdf into a FileIO Stream
	s = FileIO.load(fn * ".pdf")
	# save a png
	pngfn = fn * ".png"
	FileIO.save(pngfn, s)
	# now write from the file
	write(io, readstring(open(pngfn)))
	end
	end

it instead takes 14 seconds to precompile and 4 seconds to start when precompiled.

Just thought the numbers were interesting, that a quite small code part (which only seems to provide png output by passing through a pdf) has such a significant impact on startup time.

[Evizero]

That is quite interesting. Do you think this is FileIO's effect in general or just the way it is used here? In all the packages I work with that use FileIO I have not seen any similar effect, but then again I may just not have paid enough attention

if the @eval is the culprit, maybe depending on FileIO explicitly could improve the situation? I feel like this is quite a common package that lots of other packages also depend on

[KristofferC]

Hmm, I had FileIO take 36 seconds to load(!). But then I deleted the precompilation file and now it "only" takes 7 seconds.

Doing the experiment above again I get (24s, 9s) without commenting, and (15s, 4s) with commenting. So better, but not as dramatic as before.

[KristofferC]

It would be interesting with more data from others doing the same.

[mkborregaard]

I'd back taking on the dep if the different could be that great. Will try it out today

[KristofferC]

I'm not sure if it is the @evalor if FileIO is just slow to load on 0.6...

[Evizero]

It does seem FileIO is a bit slow

I get this after precompilation

julia> @time using FileIO
  4.163516 seconds (4.12 M allocations: 236.282 MiB, 0.88% gc time)

I did notice using Images got a bit slower to load, but I am/wasn't quite sure if I am just imagining things. Images depends on FileIO.

julia> @time using Images
  4.487465 seconds (5.04 M allocations: 265.820 MiB, 1.77% gc time)

I wonder if all this time is dominated by just this single dependency

EDIT: maybe not

julia> using FileIO

julia> @time using Images
  3.045723 seconds (3.89 M allocations: 204.888 MiB, 2.05% gc time)

[KristofferC]

I have quite a lot more allocations in my using FileIO...

julia> @time using FileIO
  7.552988 seconds (5.77 M allocations: 340.404 MiB, 3.44% gc time)

Perhaps it depends what other packages you have installed since FileIO perhaps conditionally do stuff depending on that?

[Evizero]

maybe. the above was my linux machine (where i typically work on; i.e. many packages installed). the following is my rather weak macbook (less packages installed)

julia> @time using FileIO
  3.402373 seconds (1.64 M allocations: 91.687 MiB, 8.75% gc time)

[timholy]

Performance in loading is unfortunately strongly dependent on whether you're using any package_callbacks (example packages: Requires.jl, Revise.jl) due to the need to use invokelatest as a means of preventing world-age problems. More info in timholy/Revise.jl#50 and JuliaPackaging/Requires.jl#39. It's ironic that two packages designed to reduce the pain of (re)loading code in fact lead to longer load times (on first usage). ☹️

Consequently, for anyone tracking this down, if you've customized your .juliarc.jl I recommend making sure you're running with --startup-file=no. But even with that I get some weird results. I first tried this on 0.6 and FileIO was ~4s. I then deleted most of FileIO/src/registry.jl, rebuilt FileIO, and got timings of ~0.5s. Then I restored the registry, rebuilt, and got timings of ~2s:

julia> @time using FileIO
  1.904531 seconds (1.40 M allocations: 78.818 MiB, 1.49% gc time)

Then did it again and got back up to ~4s:

julia> @time using FileIO
  3.871966 seconds (3.07 M allocations: 179.900 MiB, 1.07% gc time)

I think I had tried each enough times that OS cache shouldn't be a big factor. And in all cases I first did using Example to make sure that the loading code itself had been exercised.

One thing worth noting are some of the memory ratios reported here:

78.818 MiB : 179.900 MiB : 340.404 MiB ≈ 1 : 2 : 4

Also check this out: after a build in which using FileIO was slow, I get this:

$ ls -l ~/.julia/lib/v0.6/FileIO.ji 
-rw------- 1 tim holy 1287382 Feb  5 05:29 /home/tim/.julia/lib/v0.6/FileIO.ji

After a build in which using FileIO was fast, I get this:

$ ls -l ~/.julia/lib/v0.6/FileIO.ji 
-rw------- 1 tim holy 852048 Feb  5 05:44 /home/tim/.julia/lib/v0.6/FileIO.ji

That's weird enough that I'm calling in @vtjnash here.

[timholy]

The ratio thing may be a red herring; I just got a build of FileIO (with full registry) for which I get:

julia> @time using FileIO
  1.598653 seconds (1.01 M allocations: 56.735 MiB, 1.60% gc time)

[Evizero]

Does this behaviour also occur in 0.7?

[timholy]

I had to add using Nullables to get it to build on 0.7, but yes, it seems to:

tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no
julia> using Example

julia> @time using FileIO
  3.600703 seconds (3.65 M allocations: 191.672 MiB, 2.07% gc time)

julia> 
tim@diva:~/.julia/v0.7/FileIO/src$ ls -l ~/.julia/lib/v0.7/FileIO.ji 
-rw------- 1 tim holy 1897922 Feb  5 14:19 /home/tim/.julia/lib/v0.7/FileIO.ji
tim@diva:~/.julia/v0.7/FileIO/src$ touch FileIO.jl 
tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no -e 'using FileIO'
tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no
julia> using Example

julia> @time using FileIO
  2.297120 seconds (2.70 M allocations: 142.614 MiB, 2.93% gc time)

julia> 
tim@diva:~/.julia/v0.7/FileIO/src$ ls -l ~/.julia/lib/v0.7/FileIO.ji 
-rw------- 1 tim holy 1401622 Feb  5 14:21 /home/tim/.julia/lib/v0.7/FileIO.ji
tim@diva:~/.julia/v0.7/FileIO/src$ touch FileIO.jl 
tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no -e 'using FileIO'
tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no
julia> using Example

julia> @time using FileIO
  2.950153 seconds (2.53 M allocations: 136.272 MiB, 2.21% gc time)

julia> 
tim@diva:~/.julia/v0.7/FileIO/src$ ls -l ~/.julia/lib/v0.7/FileIO.ji 
-rw------- 1 tim holy 1904934 Feb  5 14:21 /home/tim/.julia/lib/v0.7/FileIO.ji
tim@diva:~/.julia/v0.7/FileIO/src$ touch FileIO.jl 
tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no -e 'using FileIO'
tim@diva:~/.julia/v0.7/FileIO/src$ julia-0.7 --startup-file=no -q --depwarn=no
julia> using Example

julia> @time using FileIO
  8.187372 seconds (7.58 M allocations: 401.505 MiB, 1.21% gc time)

julia> 
tim@diva:~/.julia/v0.7/FileIO/src$ ls -l ~/.julia/lib/v0.7/FileIO.ji 
-rw------- 1 tim holy 3261892 Feb  5 14:22 /home/tim/.julia/lib/v0.7/FileIO.ji

[timholy]

Filed a Julia issue: JuliaLang/julia#25900

[KristofferC]

Not sure it is worth keeping this open