Debugging invalidations

ufechner7 · December 31, 2022, 11:01am

I am testing Julia-1.9-beta2 on Ubuntu 22.04 and would like to improve the performance of plots using Bokeh.jl.

In the moment the first time to plot with this package is about 13s, and it would be nice to improve that.

Initial situation:

julia> @time @eval include("src/plot.jl")
 13.155351 seconds (18.53 M allocations: 1.189 GiB, 3.47% gc time, 117.33% compilation time)

Debug approach:

using SnoopCompile
invalidations = @snoopr begin
    # Your code goes here!
    # example for using plotting in Julia
    using Bokeh, BokehBlink
    Bokeh.settings!(display=:blink)
    
    function plot(x, y; keywords...)
        p = figure(; sizing_mode="fixed", width=1200, height=700) # stretch_both
        Bokeh.plot!(p, Bokeh.Line; x=x, y=y, color="blue", line_width=2, keywords...)
        display(p)            
    end

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

    plot(x, y1)
    nothing
end;
trees = SnoopCompile.invalidation_trees(invalidations);
@show length(SnoopCompile.uinvalidated(invalidations)) # show total invalidations
show(trees[end]) # show the most invalidated method
# Count number of children (number of invalidations per invalidated method)
n_invalidations = map(trees) do methinvs
    SnoopCompile.countchildren(methinvs)
end
import Plots
Plots.plot(
    1:length(trees),
    n_invalidations;
    markershape=:circle,
    xlabel="i-th method invalidation",
    label="Number of children per method invalidations"
)

Output:

julia> include("src/test.jl")
length(SnoopCompile.uinvalidated(invalidations)) = 512
inserting write(iod::HTTP.DebugRequest.IODebug, x::String) @ HTTP.DebugRequest ~/.julia/packages/HTTP/aTjcj/src/IODebug.jl:38 invalidated:
   backedges: 1: superseding write(io::IO, s::Union{SubString{String}, String}) @ Base strings/io.jl:244 with MethodInstance for write(::IO, ::String) (401 children)
qt.qpa.plugin: Could not find the Qt platform plugin "wayland" in ""

Questions:

How can I fix the error: “qt.qpa.plugin: Could not find the Qt platform plugin “wayland” in “””
How can I fix the most invalidated method:
inserting write(iod::HTTP.DebugRequest.IODebug, x::String) @ HTTP.DebugRequest ~/.julia/packages/HTTP/aTjcj/src/IODebug.jl:38 invalidated:
backedges: 1: superseding write(io::IO, s::Union{SubString{String}, String}) @ Base strings/io.jl:244 with MethodInstance for write(::IO, ::String) (401 children)

And in which package should the fix happen?

ranocha · December 31, 2022, 12:06pm

There is no general “simple” recipe since the reasons for invalidations can be different. You can look at Snooping on and fixing invalidations: @snoopr · SnoopCompile to learn more about this.

Impossible to say without looking deeper at it. Sometimes, you can fix invalidations by fixing the package itself. Sometimes, you need to look at Julia Base or standard libraries - or even other packages, depending on the call chains involved.

ufechner7 · December 31, 2022, 12:21pm

@ranocha Thanks for your reply!

But "…looking deeper at it. " is not exactly a scientific method. I would like to look deeper at it, but how, where to start, and what to investigate?

ranocha · December 31, 2022, 12:26pm

A good start is usually to ascend(trees[end].backedges[end]), looking at the call chains, figuring out whether there is a type instability in callers of the invalidated method that can be fixed. That’s described in the docs I linked above.

tim.holy · December 31, 2022, 1:47pm

I also recommend Julia v1.9.0-beta2 is fast - #17 by tim.holy over this approach. See discussion in Add a copy-paste invalidations analysis script by ChrisRackauckas · Pull Request #326 · timholy/SnoopCompile.jl · GitHub if you’re curious about some of the reasons why; most importantly, it allows you to focus on just the invalidations you need to fix to get precompilation working for specific workloads.

ChrisRackauckas · December 31, 2022, 2:51pm

github.com/JuliaWeb/HTTP.jl

Method invalidations

opened 08:25AM - 10 May 21 UTC

closed 10:22PM - 27 May 22 UTC

odow

client

HTTP.jl is a large cause of method invalidations in JuMP ```Julia julia> using… SnoopCompileCore julia> invalidations = @snoopr begin using HTTP end; julia> using SnoopCompile julia> trees = invalidation_trees(invalidations) 4-element Vector{SnoopCompile.MethodInvalidations}: inserting joinpath(uri::URIs.URI, parts::String...) in URIs at /Users/oscar/.julia/packages/URIs/o9DQG/src/URIs.jl:509 invalidated: mt_backedges: 1: signature Tuple{typeof(joinpath), Any, String} triggered MethodInstance for jointail(::Any, ::String) (0 children) 1 mt_cache inserting write(iod::HTTP.DebugRequest.IODebug, a...) in HTTP.DebugRequest at /Users/oscar/.julia/dev/HTTP/src/IODebug.jl:30 invalidated: backedges: 1: superseding write(io::IO, x1, xs...) in Base at io.jl:636 with MethodInstance for write(::IO, ::Int64, ::Int64, ::Int64, ::Int64) (1 children) inserting readuntil(iod::HTTP.DebugRequest.IODebug, f) in HTTP.DebugRequest at /Users/oscar/.julia/dev/HTTP/src/IODebug.jl:58 invalidated: backedges: 1: superseding readuntil(io::IO, target::AbstractString; keep) in Base at io.jl:884 with MethodInstance for readuntil(::IO, ::String) (15 children) 2: superseding readuntil(s::IO, delim::AbstractChar; keep) in Base at io.jl:771 with MethodInstance for readuntil(::IO, ::Char) (216 children) 18 mt_cache inserting write(iod::HTTP.DebugRequest.IODebug, x::String) in HTTP.DebugRequest at /Users/oscar/.julia/dev/HTTP/src/IODebug.jl:38 invalidated: backedges: 1: superseding write(io::IO, s::Union{SubString{String}, String}) in Base at strings/io.jl:185 with MethodInstance for write(::IO, ::String) (261 children) julia> length(invalidations) 1043 ``` These seem fixable. I'll take a look in the next few days unless someone beats me to it. x-ref: https://github.com/jump-dev/JuMP.jl/issues/2273

It looks like this was already fixed by removing IODebug, and you’re just on an old version of HTTP.jl

ufechner7 · December 31, 2022, 3:08pm

Not so lucky today:

(Plotting2) pkg> up
┌ Warning: could not download https://pkg.julialang.org/registries
│   exception = RequestError: HTTP/2 502 while requesting https://pkg.julialang.org/registries
└ @ Pkg.Registry ~/packages/julias/julia-1.9/share/julia/stdlib/v1.9/Pkg/src/Registry/Registry.jl:69
    Updating registry at `~/.julia/registries/General.toml`
  No Changes to `~/repos/Plotting2/Project.toml`
  No Changes to `~/repos/Plotting2/Manifest.toml`

https://eu-central.pkg.julialang.org/registries

Bad Gateway…
I think the EU server is down… Any idea how to use a different server?

Update:
This work-around worked:

import Pkg
Pkg.Registry.rm("General")
ENV["JULIA_PKG_SERVER"] = ""
Pkg.Registry.add("General")

ufechner7 · December 31, 2022, 3:37pm

OK, I see this in my Manifest.toml file:

[[deps.HTTP]]
deps = ["Base64", "Dates", "IniFile", "Logging", "MbedTLS", "NetworkOptions", "Sockets", "URIs"]
git-tree-sha1 = "0fa77022fe4b511826b39c894c90daf5fce3334a"
uuid = "cd3eb016-35fb-5094-929b-558a96fad6f3"
version = "0.9.17"

So some package depends on an old version of HTTP…

(Plotting2) pkg> add HTTP@1.6.2
   Resolving package versions...
ERROR: Unsatisfiable requirements detected for package Blink [ad839575]:
 Blink [ad839575] log:
 ├─possible versions are: 0.8.0-0.12.5 or uninstalled
 ├─restricted by compatibility requirements with BokehBlink [c7d4f63d] to versions: 0.12.5
 │ └─BokehBlink [c7d4f63d] log:
 │   ├─possible versions are: 0.1.0-0.1.1 or uninstalled
 │   └─restricted to versions * by an explicit requirement, leaving only versions: 0.1.0-0.1.1
 └─restricted by compatibility requirements with Mux [a975b10e] to versions: uninstalled — no versions left
   └─Mux [a975b10e] log:
     ├─possible versions are: 0.4.0-1.0.1 or uninstalled
     └─restricted by compatibility requirements with HTTP [cd3eb016] to versions: 1.0.0-1.0.1 or uninstalled
       └─HTTP [cd3eb016] log:
         ├─possible versions are: 0.6.10-1.6.2 or uninstalled
         └─restricted to versions 1.6.2 by an explicit requirement, leaving only versions: 1.6.2

So both Bokeh.jl and Mux.jl limit the version of HTTP.jl to an old version where this issue is not fixed…

I will create issues for these two packages…

ufechner7 · December 31, 2022, 4:04pm

The main issue is that Bokeh.jl depends on BokehBlink.jl which depends on Blink.jl which has not been updated the last 18 months…
I created an issue: BokehBlink depends on outdated Blink package · Issue #21 · cjdoris/Bokeh.jl · GitHub

Is there any alternative to Blink.jl that is better maintained?

ufechner7 · December 31, 2022, 8:34pm

Sometimes it is good to have a nap…
Just found out that:

pkg> add Blink#master

fixes the first big number of invalidations.
FTTP went down from 13.2s to 11.9s

Now looking further…

ufechner7 · January 3, 2023, 7:29pm

I now also tried the suggested approach from @tim.holy :

using SnoopCompileCore
invs = @snoopr using Bokeh, BokehBlink;
tinf = @snoopi_deep begin
        Bokeh.settings!(display=:blink)
        function plot(x, y; keywords...)
            p = figure(; sizing_mode="fixed", width=1200, height=700) # stretch_both
            Bokeh.plot!(p, Bokeh.Line; x=x, y=y, color="blue", line_width=2, keywords...)
            display(p)            
        end
        x  = 0:0.01:100
        y1 = sin.(x)
        plot(x, y1)
        nothing
    end
using SnoopCompile
trees = invalidation_trees(invs);
staletrees = precompile_blockers(trees, tinf)

Output:

julia> @time @eval include("src/find_invalidations.jl")
[ Info: Listening on: 127.0.0.1:7151, thread id: 1
 14.840208 seconds (22.39 M allocations: 1.435 GiB, 3.59% gc time, 11159.82% compilation time: <1% of which was recompilation)
2-element Vector{SnoopCompile.StaleTree}:
 inserting one(::Type{X}) where X<:FixedPoint @ FixedPointNumbers ~/.julia/packages/FixedPointNumbers/HAGk2/src/FixedPointNumbers.jl:109 invalidated:
   backedges: 1: MethodInstance for one(::Type{T} where T<:Integer) at depth 0 with 1 children blocked InferenceTimingNode: 0.000491/0.000491 on oneunit(::Type{T} where T<:Integer) with 0 direct children

 inserting ==(y::JSON3.PointerString, x::String) @ JSON3 ~/.julia/packages/JSON3/CpNms/src/strings.jl:15 invalidated:
   backedges: 1: MethodInstance for ==(::AbstractString, ::String) at depth 0 with 2 children blocked InferenceTimingNode: 0.000749/0.000939 on Logging.default_metafmt(::Base.CoreLogging.LogLevel, ::Any, ::Any, ::Any, ::Any, ::Any) with 1 direct children

Only two invalidations?

If I include the code without the debug code I get:

julia> @time @eval include("src/plot.jl")
[ Info: Listening on: 127.0.0.1:7623, thread id: 1
 10.793435 seconds (17.50 M allocations: 1.126 GiB, 3.57% gc time, 116.52% compilation time: <1% of which was recompilation)

More than 10 s compilation time, more than 1 GB allocations… Perhaps in this example the invalidations are not the main issue which costs time, but it is something else?

ChrisRackauckas · January 3, 2023, 7:47pm

Check @time_imports using Bokeh

ufechner7 · January 3, 2023, 7:54pm

julia> @time_imports using Bokeh
      0.7 ms  Statistics
     39.3 ms  FixedPointNumbers
      0.2 ms  Reexport
     58.0 ms  ColorTypes
    171.4 ms  Colors
      0.2 ms  DefaultApplication
      0.1 ms  SnoopPrecompile
     52.8 ms  Parsers
      9.3 ms  StructTypes
     52.2 ms  JSON3
      0.2 ms  DataValueInterfaces
      0.8 ms  DataAPI
      0.1 ms  IteratorInterfaceExtensions
      0.1 ms  TableTraits
      6.2 ms  OrderedCollections
     11.7 ms  Tables
    634.0 ms  Bokeh 8.13% compilation time

julia> @time_imports using BokehBlink
     12.4 ms  Observables
      0.3 ms  Requires
     27.4 ms  JSON
      0.3 ms  Pidfile
      0.7 ms  AssetRegistry
      2.6 ms  Widgets
      7.1 ms  FunctionalCollections
     20.7 ms  WebIO
     12.4 ms  MacroTools
      0.3 ms  JSExpr
     18.7 ms  Lazy
      1.5 ms  Hiccup
      1.3 ms  URIs
      2.2 ms  LoggingExtras
      0.2 ms  MbedTLS_jll
      8.4 ms  MbedTLS
      2.2 ms  BitFlags
     13.0 ms  Preferences
      0.3 ms  JLLWrappers
      3.2 ms  OpenSSL_jll 81.22% compilation time
      8.7 ms  OpenSSL
      3.0 ms  TranscodingStreams
      0.2 ms  Zlib_jll
      1.0 ms  CodecZlib
      0.2 ms  SimpleBufferStream
     23.6 ms  HTTP
      9.7 ms  Mux
      1.0 ms  Mustache
     36.0 ms  Blink 113.59% compilation time
      1.7 ms  BokehBlink

tim.holy · January 3, 2023, 7:54pm

Has that exact workload been precompiled? If you don’t want to modify the source, you can create a Startup package that precompiles that specific workload, e.g.

(@v1.10) pkg> activate .
(@v1.10) pkg> generate Startup
shell> cd Startup/
(@v1.10) pkg> activate .
(@v1.10) pkg> add Bokeh BokehBlink SnoopPrecompile

and then edit the contents of src/Startup.jl to be something like

module Startup

using Bokeh, BokehBlink
using SnoopPrecompile

function plot(x, y; keywords...)
    p = figure(; sizing_mode="fixed", width=1200, height=700) # stretch_both
    Bokeh.plot!(p, Bokeh.Line; x=x, y=y, color="blue", line_width=2, keywords...)
    display(p)            
end

@precompile_setup begin
    x  = 0:0.01:100
    y1 = sin.(x)
    @precompile_all_calls begin
        Bokeh.settings!(display=:blink)
        plot(x, y1)
    end
end

end # module Startup

Then for me:

julia> using Startup, Bokeh

julia> x  = 0:0.01:100;

julia> y1 = sin.(x);

julia> @time @eval begin
           Bokeh.settings!(display=:blink)
           Startup.plot(x, y1)
       end
[ Info: Listening on: 127.0.0.1:7888, thread id: 1
  1.559525 seconds (1.85 M allocations: 127.082 MiB, 3.95% gc time, 87.29% compilation time)

That 1.56s might be caused by the invalidations (see “87.29% compilation time”), but I’ve not checked.

ufechner7 · January 3, 2023, 8:09pm

Yes, now the TTFP is down to 3.38s!

julia> @time @eval include("src/plot.jl")
[ Info: Listening on: 127.0.0.1:4277, thread id: 1
  3.378990 seconds (5.82 M allocations: 370.667 MiB, 4.94% gc time, 55.02% compilation time)

The next question would be, could this pre-compilation already be done in the Bokeh package?

tim.holy · January 3, 2023, 9:12pm

Yes, that’s the best place for it.

ufechner7 · January 4, 2023, 11:07am

Added an issue to Bokeh.jl: Improve time to first plot using Julia 1.9-beta2 · Issue #20 · cjdoris/Bokeh.jl · GitHub

tim.holy · January 4, 2023, 3:03pm

Maybe submit a PR?