# Where are those 3 sec TTFP hiding?

**URL:** <https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615>\
**Category:** General Usage\
**Created:** [May 10, 2023, 1:59pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615 "2023-05-10T13:59:20Z")\
**Posts on this page:** 15\
**Page:** 1

<div class="post-metadata">

**Author:** ![joa-quim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/joa-quim/32/227_2.png) [@joa-quim](https://discourse.julialang.org/u/joa-quim)\
**Post date:** [May 10, 2023, 1:59pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/1 "2023-05-10T13:59:20Z")

</div>

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
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

```julia
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[]

```

---

<div class="post-metadata">

**Author:** ![Olivier\_Merchiers](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/olivier_merchiers/32/4073_2.png) [@Olivier\_Merchiers](https://discourse.julialang.org/u/Olivier_Merchiers)\
**Post date:** [May 10, 2023, 5:14pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/2 "2023-05-10T17:14:19Z")

</div>

Are you on Windows?

---

<div class="post-metadata">

**Author:** ![BeastyBlacksmith](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/beastyblacksmith/32/4741_2.png) [@BeastyBlacksmith](https://discourse.julialang.org/u/BeastyBlacksmith)\
**Post date:** [May 10, 2023, 5:17pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/3 "2023-05-10T17:17:55Z")

</div>

> [@joa-quim](#):
>
> In my `PrecompileTools` workload I have this line  
> `plot(rand(5,2))`

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

---

<div class="post-metadata">

**Author:** ![lmiq](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/lmiq/32/18314_2.png) [@lmiq](https://discourse.julialang.org/u/lmiq)\
**Post date:** [May 10, 2023, 5:20pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/4 "2023-05-10T17:20:39Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![tim.holy](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tim.holy/32/52_2.png) [@tim.holy](https://discourse.julialang.org/u/tim.holy)\
**Post date:** [May 10, 2023, 6:07pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/5 "2023-05-10T18:07:06Z")

</div>

> [@joa-quim](#):
>
> ```julia
> using GMT
> using SnoopCompileCore
> invs = @snoopr using GMT;
> 
> ```

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

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

```

then I get

```julia
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.

---

<div class="post-metadata">

**Author:** ![joa-quim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/joa-quim/32/227_2.png) [@joa-quim](https://discourse.julialang.org/u/joa-quim)\
**Post date:** [May 10, 2023, 6:18pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/6 "2023-05-10T18:18:37Z")

</div>

> [@Olivier\_Merchiers](#):
>
> Are you on Windows?

Yes.

> [@BeastyBlacksmith](#):
>
> You probably want `display(plot(rand(5,2))` there.

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

> [@lmiq](#):
>
> Is that on an empty environment? Do you have anything on startup.jl?

No, it’s in the general environment.

I have these in startup.jl

```julia
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

```julia
@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

```julia
@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

---

<div class="post-metadata">

**Author:** ![tim.holy](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tim.holy/32/52_2.png) [@tim.holy](https://discourse.julialang.org/u/tim.holy)\
**Post date:** [May 10, 2023, 6:28pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/7 "2023-05-10T18:28:21Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![joa-quim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/joa-quim/32/227_2.png) [@joa-quim](https://discourse.julialang.org/u/joa-quim)\
**Post date:** [May 10, 2023, 6:34pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/8 "2023-05-10T18:34:10Z")

</div>

> [@tim.holy](#):
>
> Once you’ve loaded GMT, that has no impact. Load SnoopCompileCore first and put all other packages inside `@snoopr`.

Well, I had actually done that too, and got

```julia
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.

---

<div class="post-metadata">

**Author:** ![tim.holy](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tim.holy/32/52_2.png) [@tim.holy](https://discourse.julialang.org/u/tim.holy)\
**Post date:** [May 10, 2023, 6:49pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/9 "2023-05-10T18:49:26Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![joa-quim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/joa-quim/32/227_2.png) [@joa-quim](https://discourse.julialang.org/u/joa-quim)\
**Post date:** [May 10, 2023, 6:57pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/10 "2023-05-10T18:57:02Z")

</div>

I will.

Related?

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

```

---

<div class="post-metadata">

**Author:** ![tim.holy](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tim.holy/32/52_2.png) [@tim.holy](https://discourse.julialang.org/u/tim.holy)\
**Post date:** [May 10, 2023, 7:00pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/11 "2023-05-10T19:00:26Z")

</div>

I don’t see that with

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

```

---

<div class="post-metadata">

**Author:** ![joa-quim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/joa-quim/32/227_2.png) [@joa-quim](https://discourse.julialang.org/u/joa-quim)\
**Post date:** [May 10, 2023, 7:07pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/12 "2023-05-10T19:07:38Z")

</div>

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

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

```

---

<div class="post-metadata">

**Author:** ![tim.holy](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tim.holy/32/52_2.png) [@tim.holy](https://discourse.julialang.org/u/tim.holy)\
**Post date:** [May 10, 2023, 7:13pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/13 "2023-05-10T19:13:12Z")

</div>

Something’s messed up for you.

```julia
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`.

---

<div class="post-metadata">

**Author:** ![joa-quim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/joa-quim/32/227_2.png) [@joa-quim](https://discourse.julialang.org/u/joa-quim)\
**Post date:** [May 10, 2023, 7:21pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/14 "2023-05-10T19:21:43Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![tim.holy](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tim.holy/32/52_2.png) [@tim.holy](https://discourse.julialang.org/u/tim.holy)\
**Post date:** [May 10, 2023, 8:35pm UTC](https://discourse.julialang.org/t/where-are-those-3-sec-ttfp-hiding/98615/15 "2023-05-10T20:35:36Z")

</div>

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