SnoopPrecompiling makes absolutely no difference in TTFP

[joa-quim]

GMT.jl here (again :)) and on Windows

Without the Snoop

  | | |_| | | | (_| |  |  Version 1.9.0-DEV.1512 (2022-10-05)
 _/ |\__'_|_|_|\__'_|  |  Commit fbd5a72b0a (12 days old master)
|__/                   |

julia> cd("C:/v"); @time using GMT
[ Info: Precompiling GMT [5752ebe1-31b9-557e-87aa-f909b540aa54]
 28.278143 seconds (2.12 M allocations: 162.068 MiB, 0.22% gc time, 5.04% compilation time: 52% of which was recompilation)

julia> tic(); plot(rand(5,2)); toc()
elapsed time: 8.2714632 seconds
8.2714632

Now, uncomment the lines https://github.com/GenericMappingTools/GMT.jl/blob/master/src/GMT.jl#L299 (plus the one in Project.toml), and the precompile time indeed increases but run time is the same

  | | |_| | | | (_| |  |  Version 1.9.0-DEV.1512 (2022-10-05)
 _/ |\__'_|_|_|\__'_|  |  Commit fbd5a72b0a (12 days old master)
|__/                   |

julia> cd("C:/v"); @time using GMT
[ Info: Precompiling GMT [5752ebe1-31b9-557e-87aa-f909b540aa54]
 35.410896 seconds (2.61 M allocations: 190.210 MiB, 0.17% gc time, 4.02% compilation time: 52% of which was recompilation)

julia> tic(); plot(rand(5,2)); toc()
elapsed time: 7.8585027 seconds
7.8585027

Note, I use the old tic(), toc() because @time clearly underestimates the true time by 2 or 3 times.

[Krastanov]

Does @time @eval ... also underestimate?

Also, SnoopPrecompile is not a panacea, see this post https://sciml.ai/news/2022/09/21/compile_time/

In particular, even after precompilation, Julia might not be capable of caching everything (Tim Holy is actually actively adding more compilation caching capabilities to Julia). Take Makie for example. Even with precompilation TTFX takes more than 20s. However, precompilation + a custom sysimage leads to TTFX that is less than a second.

Basically, SnoopPrecompile + a custom sysimage probably would make things fast. SnoopPrecompile on its own helpful, but it is not sufficient until more compilation caching capabilities are added to Julia (which is in progress).

[joa-quim]

OK, part of this answer is mostly for Tim.

julia> cd("C:/v"); @time using GMT
[ Info: Precompiling GMT [5752ebe1-31b9-557e-87aa-f909b540aa54]
 29.168149 seconds (3.02 M allocations: 213.137 MiB, 0.32% gc time, 4.97% compilation time: 51% of which was recompilation)

julia> @time @eval plot(rand(5,2));
  8.200281 seconds (1.85 M allocations: 94.301 MiB, 0.36% gc time, 99.94% compilation time)

Thanks, I know that blog and that's where I learned about the ambiguities, which I reduced from 142 to 9 (last 9 make no sense to me). I also have almost no invalidations. What I still have is 16 inference issues, which I'm sure are the source of latency but that's exactly where I thought SnoopPrecompile would come to rescue.

julia> using SnoopCompile

julia> tinf = @snoopi_deep plot(rand(5,2))
InferenceTimingNode: 7.929306/12.506911 on Core.Compiler.Timings.ROOT() with 16 direct children

julia> itrigs = inference_triggers(tinf)
16-element Vector{InferenceTrigger}:

And why I say I'm sure?
Because the GMT.jl is a wrapper of the GMT lib and mostly what it does is to parse the high level kwargs options into a string that is passed to the lower level code that interfaces with the C lib. And

plot(rand(5,2)) translates in fact to a call like

gmt("psxy  -JX14c/9.5c -Baf -BWSen -R0.16/0.84/0.32/0.98 -P -K > C:\\TEMP\\GMTjl_tmp.ps", rand(5,2))

and if I use the lower level call directly (and here the above inferences are no longer an issue) the TTFP shrinks to 0.8 sec

  | | |_| | | | (_| |  |  Version 1.9.0-DEV.1512 (2022-10-05)
 _/ |\__'_|_|_|\__'_|  |  Commit fbd5a72b0a (12 days old master)
|__/                   |

julia> cd("C:/v"); @time using GMT
  2.755532 seconds (2.97 M allocations: 210.384 MiB, 3.33% gc time, 51.06% compilation time: 53% of which was recompilation)

julia> @time @eval gmt("psxy  -JX14c/9.5c -Baf -BWSen -R0.16/0.84/0.32/0.98 -P -K > C:\\TEMP\\GMTjl_tmp.ps", rand(5,2))
psxy [WARNING]: Your plot (WxH = 14.00 x 9.50 cm) placed at (20.00, 20.00 cm) may exceed your PS_MEDIA (WxH = 20.99 x 29.70 cm)
  0.799798 seconds (100.53 k allocations: 4.337 MiB, 99.28% compilation time)

[timholy]

Given discussions on discourse, I believe that this is demonstrably fixed now (remedy: fix invalidations).