Where are those 3 sec TTFP hiding?

General Usage
1

In my PrecompileTools workload I have this line
plot(rand(5,2))

But when I run it again on a fresh session, I see

julia> @time @eval plot(rand(5,2))
  3.232747 seconds (7.55 M allocations: 479.328 MiB, 5.31% gc time, 99.87% compilation time: 94% of which was recompilation)

So, it’t telling me that almost all of those ~3 seconds (the variability here goes > 0.5 sec) are spent recompiling code.

But when I run that script that Tim has put up for us, it tells me there are no invalidations. So where are those recompilations coming from?

…

In a new fresh session

using GMT
using SnoopCompileCore
invs = @snoopr using GMT;
tinf = @snoopi_deep GMT.plot(rand(5,2));
using SnoopCompile
trees = invalidation_trees(invs);
taletrees = precompile_blockers(trees, tinf)
SnoopCompile.StaleTree[]
2 Likes
2

Are you on Windows?

3

You probably want display(plot(rand(5,2)) there. (might not solve the issue at hand though)

1 Like
4

Is that on an empty environment? Do you have anything on startup.jl?

5

Once you’ve loaded GMT, that has no impact. Load SnoopCompileCore first and put all other packages inside @snoopr.

That said, it does look like precompile_blockers is missing something; I’ve had to make quite a few changes to track changes in Julia 1.9/1.10 and I’ve probably introduced a bug. If I use

thinned =  filtermod(GMT, trees; recursive=true)

then I get

julia> tree
inserting eltype(::Type{JuliaInterpreter.ExprSplitter}) @ JuliaInterpreter ~/.julia/packages/JuliaInterpreter/ktCFr/src/construct.jl:438 invalidated:
   backedges: 1: superseding eltype(::Type) @ Base abstractarray.jl:233 with MethodInstance for eltype(::Type) (61 children)
              2: superseding eltype(::Type) @ Base abstractarray.jl:233 with MethodInstance for eltype(::Type) (30 children)

So JuliaInterpreter (used by the debugger and by Revise) is invalidating some of the code in GMT. You can ascend to figure out the cause and hopefully fix the invalidation.

2 Likes
6

Yes.

I don’t think so. Note that this plot is GMT.plot, not Plots.plot.

No, it’s in the general environment.

I have these in startup.jl

using Revise, Dates, Printf
Base.show(io::IO, x::T) where {T<:Union{UInt16, UInt8, UInt32, UInt64}} = Base.print(io, x)

and had previously looked at their effect, but repeating, in spite of a large variability, Dates and Printf seems to have no effect but Revise and the other (this is is because I hate unsigned ints being displayed in hexadecimal) do have.

Without Revise

@time @eval plot(rand(5,2))
  2.183093 seconds (4.72 M allocations: 290.435 MiB, 5.75% gc time, 99.75% compilation time: 85% of which was recompilation)

without Revise & Base.show

@time @eval plot(rand(5,2))
  0.981926 seconds (1.29 M allocations: 85.012 MiB, 2.84% gc time, 99.50% compilation time: 67% of which was recompilation)

But note that in all cases it says most of time is used in recompilation

7

You know you can answer these question with ProfileView.view(flamegraph(tinf)) and then click on the bars?

8

Well, I had actually done that too, and got

julia> include("test_gmt1.jl")
1-element Vector{SnoopCompile.StaleTree}:
 inserting eltype(::Type{JuliaInterpreter.ExprSplitter}) @ JuliaInterpreter C:\Users\j\.julia\packages\JuliaInterpreter\ktCFr\src\construct.jl:438 invalidated:
   backedges: 1: MethodInstance for eltype(::Type) at depth 1 with 18 children blocked 0.8874338000000002 inclusive time for 2 nodes

but did not know what to do with this info. Even tried to comment that src\construct.jl:438 line but things came out much slower.

9

As usual, you have to fix the type-unstable code in GMT. (That’s a lot easier now that Cthulhu is user-friendly.) Or, now (with PrecompileTools 1.1 and higher) you can create a personal GMTStartup package, and load both Revise & GMT under @recompile_invalidations.

But it looks like SnoopCompile has bugs due to some of the changes. There are clearly invalidations to GMT code that it’s not inserting into trees. Can you please file an issue at SnoopCompile?

1 Like
10

I will.

Related?

julia> ProfileView.view(flamegraph(tinf))
ERROR: MethodError: no method matching iterate(::SnoopCompileCore.InferenceTimingNode)
11

I don’t see that with

  [c46f51b8] ProfileView v1.7.1
  [aa65fe97] SnoopCompile v2.10.7
  [e2b509da] SnoopCompileCore v2.10.0
12

That’s what I have too. Plus [08572546] FlameGraphs v1.0.0. That is needed to right? Otherwise the error is

ProfileView.view(flamegraph(tinf))
ERROR: UndefVarError: `flamegraph` not defined
13

Something’s messed up for you.

julia> using SnoopCompile

julia> flamegraph
flamegraph (generic function with 3 methods)

julia> methods(flamegraph)
# 3 methods for generic function "flamegraph" from FlameGraphs:
 [1] flamegraph()
     @ ~/.julia/packages/FlameGraphs/ASDAh/src/graph.jl:100
 [2] flamegraph(tinf::SnoopCompileCore.InferenceTimingNode; tmin, excluded_modules, mode)
     @ SnoopCompile ~/.julia/packages/SnoopCompile/dK7kp/src/parcel_snoopi_deep.jl:1788
 [3] flamegraph(data; lidict, C, combine, recur, norepl, pruned, filter, threads, tasks)
     @ ~/.julia/packages/FlameGraphs/ASDAh/src/graph.jl:100

SnoopCompile re-exports flamegraph while adding methods to it. Maybe you forgot to say using SnoopCompile.

14

Yes, sorry, I hadn’t do the using SnoopCompile. And good news, ProfileView used to render the Julia session unbearably slow (this has been mentioned time to time here in forum) but this time I see no such effect. But I’m also on a fresh new laptop.

1 Like
15

It’s probably less the hardware and more that Windows has gotten better. But that’s great to hear!