JET.jl reports error for every `println`

General Usage
1

JET.jl reports run-time dispatch errors for every println, even if the println line in question is not reached. Is that desired? (it makes harder to check for errors in any package that prints information optionally for debugging, like many optimization routines do).

julia> function f(x,c)
           if c
               println("c is true")
           end
           return x + 1
       end
f (generic function with 1 method)

julia> @report_opt f(1,false)
═════ 6 possible errors found ═════
┌ @ REPL[4]:3 Main.println("c is true")
│┌ @ coreio.jl:4 Base.println(Core.tuple(Core.typeassert(Base.stdout, Base.IO)), xs...)
││┌ @ strings/io.jl:75 Base.print(Core.tuple(io), xs, Core.tuple("\n")...)
│││┌ @ strings/io.jl:43 Base.lock(io)
││││┌ @ show.jl:334 Base.lock(Base.getproperty(io, :io))
│││││┌ @ stream.jl:282 Base.lock(Base.getproperty(s, :lock))
││││││┌ @ lock.jl:100 Base.wait(Base.getproperty(rl, :cond_wait))
│││││││┌ @ condition.jl:123  = Base.wait()
││││││││┌ @ task.jl:837 result = Base.try_yieldto(Base.ensure_rescheduled)
│││││││││┌ @ task.jl:774 Base.getproperty(%7, :result)
││││││││││ runtime dispatch detected: Base.getproperty(%7::Task, :result::Symbol)
│││││││││└───────────────
│││││││││┌ @ task.jl:775 Base.setproperty!(%7, :result, Base.nothing)
││││││││││ runtime dispatch detected: Base.setproperty!(%7::Task, :result::Symbol, Base.nothing)
│││││││││└───────────────
│││││││││┌ @ task.jl:776 Base.setproperty!(%7, :_isexception, false)
││││││││││ runtime dispatch detected: Base.setproperty!(%7::Task, :_isexception::Symbol, false)
│││││││││└───────────────
│││││││┌ @ condition.jl:125 Base.list_deletefirst!(Base.getproperty(ct, :queue), ct)
││││││││┌ @ linked_list.jl:145 Base.isequal(Base.getproperty(h, :value), val)
│││││││││┌ @ gcutils.jl:4 Base.isequal(%1, v)
││││││││││ runtime dispatch detected: Base.isequal(%1::Any, v::Task)
│││││││││└────────────────
│││││││┌ @ condition.jl:125 Base.list_deletefirst!(%25, %19)
││││││││ runtime dispatch detected: Base.list_deletefirst!(%25::Any, %19::Task)
│││││││└────────────────────
│┌ @ coreio.jl:4 Base.println(%3, %4)
││ runtime dispatch detected: Base.println(%3::IO, %4::String)
│└───────────────
2

It seems there was some work on ignored_patterns but I didn’t find any mention of it in the documentation. In general I’m also pretty unsure about expected dynamic dispatch especially with regard to Base methods. Therefore I mostly try to separate my performance critical code.

3

Whether you think of it as a bug or a feature, SnoopCompile can only detect runtime dispatch when you first infer the code. That means each runtime dispatch appears at most once. Some common runtime dispatch is already precompiled (like this case) so it doesn’t even show up.

julia> using SnoopCompile

julia> function f(x, c)
           if c
               println("c is true")
           end
           return x + 1
       end
f (generic function with 1 method)

julia> g(xc, c) = f(xc[1], c)
g (generic function with 1 method)

julia> tinf = @snoopi_deep g(Any[1], true)
c is true
InferenceTimingNode: 0.064309/0.067146 on Core.Compiler.Timings.ROOT() with 2 direct children

julia> itrigs = inference_triggers(tinf)
2-element Vector{InferenceTrigger}:
 Inference triggered to call g(::Vector{Any}, ::Bool) from eval (./boot.jl:370) inlined into REPL.eval_user_input(::Any, ::REPL.REPLBackend) (/home/tim/src/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:151)
 Inference triggered to call f(::Int64, ::Bool) from g (./REPL[3]:1) with specialization g(::Vector{Any}, ::Bool)

The first trigger is just from your call at the REPL. The second is for dispatching to f based on a value extracted from a Vector{Any}, which naturally forces runtime dispatch. But the println-related runtime dispatches don’t show up because they were already compiled.

Just make sure you always use a fresh session for each new @snoopi_deep.

When you want to understand the cause of the runtime dispatch, use ascend:

julia> ascend(itrigs[end])
Choose a call for analysis (q to quit):
 >   f(::Int64, ::Bool)
       g(::Vector{Any}, ::Bool) at ./REPL[3]:1
         eval at ./boot.jl:370 => eval_user_input(::Any, ::REPL.REPLBackend) at /home/tim/src/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:151
           repl_backend_loop(::REPL.REPLBackend) at /home/tim/src/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:247
             start_repl_backend(::REPL.REPLBackend, ::Any) at /home/tim/src/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:232
               #run_repl#47(::Bool, ::typeof(REPL.run_repl), ::REPL.AbstractREPL, ::Any) at /home/tim/src/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:369
                 run_repl(::REPL.AbstractREPL, ::Any) at /home/tim/src/julia-master/usr/share/julia/stdlib/v1.9/REPL/src/REPL.jl:356
                   (::Base.var"#962#964"{Bool, Bool, Bool})(::Module) at ./client.jl:419
                     #invokelatest#2 at ./essentials.jl:729 => invokelatest at ./essentials.jl:727 => run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool) at ./client.jl:404
v                      exec_options(::Base.JLOptions) at ./client.jl:318

Hit the down arrow and then enter, and then you’ll be in a Cthulhu session where you can see the reason for the runtime dispatch.

1 Like