Time to first plot with system image not as good as expected

General Usage
,
1

I am trying to reduce the time-to-first-plot by using a system image. What I am doing is explained in detail here: GitHub - ufechner7/Plotting: Demo for using InspectDR

If you are using Linux you can easily reproduce my results.

Without system image:

ufechner@TUD277255:~/repos/Plotting$ julia --project
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.8.1 (2022-09-06)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

julia> @time include("src/plot.jl")
To zoom, draw a rectangle while keeping the right mouse key pressed!
To go back to see the full graph, press <CTRL><f>
 15.647398 seconds (38.22 M allocations: 2.047 GiB, 4.96% gc time, 79.17% compilation time: 12% of which was recompilation)

With system image:

ufechner@TUD277255:~/repos/Plotting$ asysimg --project
┌ Info: The package AutoSysimages.jl started!
│  Loaded sysimage:    /home/ufechner/.julia/asysimg/1.8.1/23ZRuw/asysimg-2022-09-18T12-39-40.634.so
│  Active directory:   /home/ufechner/.julia/asysimg/1.8.1/23ZRuw
│  Global snoop file:  /home/ufechner/.julia/asysimg/1.8.1/23ZRuw/snoop-file.jl
└  Tmp. snoop file:    /tmp/jl_1yJIleFuBE-snoop.jl
┌ Warning: Function 'pkgversion' is needed to check versions.
└ @ AutoSysimages ~/.julia/packages/AutoSysimages/LTaGS/src/AutoSysimages.jl:375
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.8.1 (2022-09-06)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

asysimg> @time include("src/plot.jl")
To zoom, draw a rectangle while keeping the right mouse key pressed!
To go back to see the full graph, press <CTRL><f>
  7.374812 seconds (20.07 M allocations: 1.012 GiB, 7.48% gc time, 99.52% compilation time)

Why do I have still 99.5% compilation time even though I am using a system image?

2

Could it be that the fact that I am using Gtk.shortNames, but Gtk is in the Project.toml file confuses AutoSysimages or PackageCompiler?

using Gtk.ShortNames, InspectDR

function init()
    inspectdr()
    InspectDR.defaults.xaxiscontrol_visible = false
    default(width=2, xtickfontsize=12, ytickfontsize=12, legendfontsize=12)
end

function plot(params...; keywords...)
    p = Plots.plot(params...; keywords...)
    pIDR = display(p)            # Display with InspectDR and keep plot object
    resize!(pIDR.wnd, 1200, 700) # Resize GTK window directly
    G_.keep_above(pIDR.wnd, true)
end
3

How much snoopprecompilation is setup in InspectDR?

4

But why should that matter? AutoSysimage is recording the commands I executed on the command line…

5

Does it have the special handling of dynamic dispatching code that SnoopPrecompile.jl has? Generally calls after a dynamic dispatch are dropped from things which build precompile files, and SnoopPrecompile.jl specifically fixes that and I’ve seen that cause dramatic differences. I am curious whether AutoSysimage took the care to handle that (or how it’s building its trace)

6

Just as update, the TTFP is now down from 7.4s to 5.5s… Not so sure why, I guess the new version of Plots.jl made the difference, could also be something else…

Allocations also went down a lot:

asysimg> @time include("src/plot.jl")
To zoom, draw a rectangle while keeping the right mouse key pressed!
To go back to see the full graph, press <CTRL><f>
    5.473786 seconds (14.53 M allocations: 755.695 MiB, 9.02% gc time, 99.41% compilation time)
7

A bit tangential, as it is not the same plotting library, but I am getting something a bit better when using Makie on current Julia master.

With a sysimage that took just a couple of clicks to prepare in vscode:

julia> @time @eval using CairoMakie
  0.008680 seconds (14.54 k allocations: 927.412 KiB)

julia> @time plot([1,2,3])
  2.082096 seconds (1.94 M allocations: 130.274 MiB, 2.15% gc time, 37.41% compilation time)

Without a custom sysimage:

julia> @time @eval using CairoMakie
 13.082514 seconds (17.49 M allocations: 1.247 GiB, 4.57% gc time, 3.01% compilation time: <1% of which was recompilation)

# don't even bother actually making the first plot, it takes more than 30 seconds
1 Like
8

Well, did you include the time to display the plot?
Like:

using CairoMakie
@time (p=plot([1,2,3]); display(p))

And if I try this in the repl, not even a plot window pops up. :frowning:

9

Pardon the lack of clarity, this was in vscode where there is a custom show method that makes a plot show up. Yes, that time was included. With GLMakie instead of CairoMakie you can get an independent OpenGL window. That takes 4 seconds with my sysimage.

10

Using this code:

using GLMakie

f = Figure()
ax = Axis(f[1, 1])

x  = 0:0.01:100
y = sin.(x)

lines!(ax, x, y)
display(f)

I get:

asysimg> @time include("src/plot.jl")
  3.153288 seconds (2.45 M allocations: 153.219 MiB, 1.13% gc time, 52.23% compilation time)
GLMakie.Screen(...)

So 3.2s FTTP for GLMakie + system image vs. 5.5s for InspectDR + Plots + system image…

But without system image InspectDR is much faster…
And as far as I know you cannot use GLMakie together with Plots…

11

I think nonzero compilation time means you haven’t traced all the compilations to include in your system image, unless the package uses closures that resist compilation.

12

Well, I am using AutoSysimages.jl …