kwfunc drops the nospecialize annotation #34516

timholy · 2020-01-26T14:08:48Z

If we annotate all arguments as @nospecialize, this annotation gets applied to both the main method and the "body method". But it doesn't get applied to the Core.kwfunc(f). Demo:

julia> ex = quote
       function f(a, b; c=1, kwargs...)
           @nospecialize
           return a + b + c
       end
       end
quote
    #= REPL[16]:2 =#
    function f(a, b; c=1, kwargs...)
        #= REPL[16]:3 =#
        #= REPL[16]:3 =# @nospecialize
        #= REPL[16]:4 =#
        return a + b + c
    end
end

julia> Meta.lower(Main, ex)
:($(Expr(:thunk, CodeInfo(
    @ REPL[16]:2 within `top-level scope'
1 ─       $(Expr(:thunk, CodeInfo(
    @ none within `top-level scope'
1 ─     return $(Expr(:method, :f))
)))
│         $(Expr(:thunk, CodeInfo(
    @ none within `top-level scope'
1 ─     return $(Expr(:method, Symbol("#f#34")))
)))
│         $(Expr(:method, :f))
│         $(Expr(:method, Symbol("#f#34")))
│   %5  = Core.typeof(var"#f#34")
│   %6  = Core.Typeof(f)
│   %7  = Core.svec(%5, Core.Any, Core.Any, %6, Core.Any, Core.Any)
│   %8  = Core.svec()
│   %9  = Core.svec(%7, %8)
│         $(Expr(:method, Symbol("#f#34"), :(%9), CodeInfo(quote
    $(Expr(:meta, :nospecialize))
    a + b + c
    return %2
end)))
│         $(Expr(:method, :f))
│   %12 = Core.Typeof(f)
│   %13 = Core.svec(%12, Core.Any, Core.Any)
│   %14 = Core.svec()
│   %15 = Core.svec(%13, %14)
│         $(Expr(:method, :f, :(%15), CodeInfo(quote
    $(Expr(:meta, :nospecialize))
    Core.NamedTuple()
    Base.pairs(%2)
    var"#f#34"(1, %3, #self#, a, b)
    return %4
end)))
│         $(Expr(:method, :f))
│   %18 = Core.Typeof(f)
│   %19 = Core.kwftype(%18)
│   %20 = Core.Typeof(f)
│   %21 = Core.svec(%19, Core.Any, %20, Core.Any, Core.Any)
│   %22 = Core.svec()
│   %23 = Core.svec(%21, %22)
│         $(Expr(:method, :f, :(%23), CodeInfo(quote
    Core.NewvarNode(:(kwargs...))
    Base.haskey(@_2, :c)
    unless %2 goto %6
    @_8 = Base.getindex(@_2, :c)
    goto %7
    @_8 = 1
    c = @_8
    Core.tuple(:c)
    Core.apply_type(Core.NamedTuple, %8)
    Base.structdiff(@_2, %9)
    kwargs... = Base.pairs(%10)
    var"#f#34"(c, kwargs..., @_3, a, b)
    return %12
end)))
│   %25 = f
│   %26 = Core.ifelse(false, false, %25)
└──       return %26
))))

I noticed this because I've got most of ImageView annotated with @nospecialize, yet when I run SnoopCompile, check out the worst offenders:

# After already running the tests once in the same Julia session
julia> tinf = @snoopi tmin=0.01 include("runtests.jl");

julia> for tmi in tinf[end-4:end]
           println(tmi, '\n')
       end
(0.02242422103881836, MethodInstance for (::ImageView.var"#kw##imshow")(::NamedTuple{(:name, :aspect),Tuple{String,Symbol}}, ::typeof(imshow), ::Main.ConeModule.Cone{RGB{Normed{UInt8,8}}}, ::Signal{ZoomRegion{RoundingIntegers.RInt64}}, ::ImageView.SliceData{false,2,Tuple{Axis{1,Base.OneTo{Int64}},Axis{4,Base.OneTo{Int64}}}}))

(0.027924776077270508, MethodInstance for (::var"#kw##imshow_now")(::NamedTuple{(:name,),Tuple{String}}, ::typeof(imshow_now), ::Main.ConeModule.Cone{RGB{Normed{UInt8,8}}}))

(0.08399486541748047, MethodInstance for (::ImageView.var"#kw##imshow")(::NamedTuple{(:name, :aspect),Tuple{String,Symbol}}, ::typeof(imshow), ::Main.ConeModule.Cone{RGB{Normed{UInt8,8}}}, ::Signal{ZoomRegion{RoundingIntegers.RInt64}}, ::ImageView.SliceData{false,2,Tuple{Axis{3,Base.OneTo{Int64}},Axis{4,Base.OneTo{Int64}}}}))

(0.20128607749938965, MethodInstance for (::var"#kw##imshow_now")(::NamedTuple{(:scalei,),Tuple{var"#20#21"}}, ::typeof(imshow_now), ::Array{Gray{Float32},2}))

(0.4840118885040283, MethodInstance for (::ImageView.var"#kw##imshow")(::NamedTuple{(:name, :aspect),Tuple{String,Symbol}}, ::typeof(imshow), ::MappedArrays.ReadonlyMappedArray{RGB{Normed{UInt8,8}},2,Array{Gray{Float32},2},var"#20#21"}, ::Signal{CLim{RGB{Float64}}}, ::Signal{ZoomRegion{RoundingIntegers.RInt64}}, ::ImageView.SliceData{false,0,Tuple{}}))

(The format is (inferencetime, methodinstance).)

This is on ImageView 0.10.5.

The text was updated successfully, but these errors were encountered:

KristofferC · 2020-01-26T14:17:51Z

A bit similar in spirit to #30411 (and JuliaArrays/StaticArrays.jl#659 (comment)).

timholy · 2020-05-23T15:48:27Z

I'm tagging this with "latency." With progress in reducing invaliations, precompile directives are getting more effective, and so this issue is starting to be one of the standout issues. I'm testing this on #35928, where Revise now has zero invalidations, and local branches of JuliaInterpreter, LoweredCodeUtils, and Revise with some extra precompile directives that formerly weren't effective but now are.

Julia 1.4:

julia> using SnoopCompile

julia> tinf = @snoopi tmin=0.01 using Revise
8-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.012759923934936523, MethodInstance for setindex!(::Dict{Base.PkgId,Revise.PkgData}, ::Revise.PkgData, ::Base.PkgId))
 (0.013189077377319336, MethodInstance for setindex!(::Dict{Method,Nothing}, ::Nothing, ::Method))
 (0.013219833374023438, MethodInstance for setindex!(::Dict{Base.PkgId,CodeTracking.PkgFiles}, ::CodeTracking.PkgFiles, ::Base.PkgId))
 (0.013393163681030273, MethodInstance for setindex!(::Dict{String,Revise.WatchList}, ::Revise.WatchList, ::String))
 (0.01339578628540039, MethodInstance for setindex!(::Dict{String,Base.PkgId}, ::Base.PkgId, ::String))
 (0.014921903610229492, MethodInstance for setindex!(::Dict{Module,Nothing}, ::Nothing, ::Module))
 (0.018869876861572266, MethodInstance for setindex!(::OrderedCollections.OrderedDict{Module,OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}}, ::OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}, ::Module))
 (0.04966402053833008, MethodInstance for stale_cachefile(::String, ::String))

julia> tinf = @snoopi tmin=0.01 includet("/home/tim/tmp/revise_data_code.jl")
14-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.01052713394165039, MethodInstance for get(::Dict{Any,Any}, ::Tuple{QuoteNode,DataType,Core.SimpleVector,Module,Int64}, ::Nothing))
 (0.012382030487060547, MethodInstance for _accumulate1!(::typeof(Base.add_sum), ::Array{Int64,1}, ::Int64, ::Array{Int64,1}, ::Int64))
 (0.012686014175415039, MethodInstance for setindex!(::Dict{Symbol,Array{Int64,1}}, ::Array{Int64,1}, ::Symbol))
 (0.017424821853637695, MethodInstance for setindex!(::Dict{Union{GlobalRef, Symbol},Revise.Uses}, ::Revise.Uses, ::Symbol))
 (0.017566919326782227, MethodInstance for setindex!(::OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}, ::Array{Any,1}, ::Revise.RelocatableExpr))
 (0.021029949188232422, MethodInstance for #methoddef!#3(::Bool, ::typeof(LoweredCodeUtils.methoddef!), ::Any, ::Array{Any,1}, ::JuliaInterpreter.Frame, ::Any, ::Int64))
 (0.021709918975830078, MethodInstance for unique!(::Array{Int64,1}))
 (0.031141996383666992, MethodInstance for (::LoweredCodeUtils.var"#methoddef!##kw")(::NamedTuple{(:define,),Tuple{Bool}}, ::typeof(LoweredCodeUtils.methoddef!), ::Function, ::Array{Any,1}, ::JuliaInterpreter.Frame, ::Expr, ::Int64))
 (0.0334320068359375, MethodInstance for build_compiled_call!(::Expr, ::Symbol, ::Core.CodeInfo, ::Int64, ::Int64, ::Array{Symbol,1}, ::Module))
 (0.053552865982055664, MethodInstance for #methods_by_execution!#17(::Bool, ::Bool, ::Base.Iterators.Pairs{Symbol,Bool,Tuple{Symbol},NamedTuple{(:skip_include,),Tuple{Bool}}}, ::typeof(Revise.methods_by_execution!), ::Any, ::Revise.CodeTrackingMethodInfo, ::Dict{Module,Array{Expr,1}}, ::Module, ::Expr))
 (0.05588388442993164, MethodInstance for #split_expressions!#29(::Bool, ::String, ::typeof(JuliaInterpreter.split_expressions!), ::Array{Tuple{Module,Expr},1}, ::Dict{Module,Array{Expr,1}}, ::Expr, ::Module, ::Expr))
 (0.07006096839904785, MethodInstance for setindex!(::OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}, ::Nothing, ::Revise.RelocatableExpr))
 (0.19635796546936035, MethodInstance for (::Revise.var"#methods_by_execution!##kw")(::NamedTuple{(:define,),Tuple{Bool}}, ::typeof(Revise.methods_by_execution!), ::Function, ::Revise.CodeTrackingMethodInfo, ::Dict{Module,Array{Expr,1}}, ::JuliaInterpreter.Frame, ::BitArray{1}))
 (0.39952611923217773, MethodInstance for step_expr!(::Any, ::JuliaInterpreter.Frame, ::Any, ::Bool))

julia> sum(first, tinf)
0.9532825946807861

Latest on everything:

julia> tinf = @snoopi tmin=0.01 using Revise
4-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.011095046997070312, MethodInstance for setindex!(::Dict{String,Revise.WatchList}, ::Revise.WatchList, ::String))
 (0.011210918426513672, MethodInstance for setindex!(::Dict{Base.PkgId,CodeTracking.PkgFiles}, ::CodeTracking.PkgFiles, ::Base.PkgId))
 (0.012675046920776367, MethodInstance for setindex!(::Dict{Base.PkgId,Revise.PkgData}, ::Revise.PkgData, ::Base.PkgId))
 (0.031787872314453125, MethodInstance for setindex!(::OrderedCollections.OrderedDict{Module,OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}}, ::OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}, ::Module))

julia> tinf = @snoopi tmin=0.01 includet("/home/tim/tmp/revise_data_code.jl")
11-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.010179996490478516, MethodInstance for setindex!(::Dict{Symbol,Array{Int64,1}}, ::Array{Int64,1}, ::Symbol))
 (0.010679960250854492, MethodInstance for unique!(::Array{Int64,1}))
 (0.010960817337036133, MethodInstance for _accumulate1!(::typeof(Base.add_sum), ::Array{Int64,1}, ::Int64, ::Array{Int64,1}, ::Int64))
 (0.011637210845947266, MethodInstance for setindex!(::Dict{Union{GlobalRef, Symbol},Array{Int64,1}}, ::Array{Int64,1}, ::Symbol))
 (0.012096881866455078, MethodInstance for _append!(::Array{Int64,1}, ::Base.HasLength, ::BitSet))
 (0.012166023254394531, MethodInstance for setindex!(::Dict{Union{GlobalRef, Symbol},LoweredCodeUtils.Variable}, ::LoweredCodeUtils.Variable, ::Symbol))
 (0.014883041381835938, MethodInstance for setindex!(::Dict{Union{GlobalRef, Symbol},LoweredCodeUtils.Links}, ::LoweredCodeUtils.Links, ::Symbol))
 (0.017047882080078125, MethodInstance for setindex!(::Dict{Union{GlobalRef, Symbol},Nothing}, ::Nothing, ::Symbol))
 (0.026586055755615234, MethodInstance for merge(::NamedTuple{(:filename,),Tuple{String}}, ::Base.Iterators.Pairs{Symbol,Bool,Tuple{Symbol},NamedTuple{(:extract_docexprs,),Tuple{Bool}}}))
 (0.034136056900024414, MethodInstance for setindex!(::OrderedCollections.OrderedDict{Revise.RelocatableExpr,Union{Nothing, Array{Any,1}}}, ::Nothing, ::Revise.RelocatableExpr))
 (0.04282689094543457, MethodInstance for (::JuliaInterpreter.var"#prepare_framecode##kw")(::NamedTuple{(:enter_generated,),Tuple{Bool}}, ::typeof(JuliaInterpreter.prepare_framecode), ::Method, ::Type{T} where T))

julia> sum(first, tinf)
0.2032008171081543

(I'll take a 5-fold speedup anytime!) The biggest remaining contributor stems from the specialization ::Type{T} where T in the kwfunc but not the "parent".

With progress in eliminating invalidations, these didn't used to help but now they do. xref JuliaLang/julia#34516 (comment)

JeffBezanson · 2020-05-23T16:13:39Z

Have you added @optlevel 1 to ImageView?

timholy · 2020-05-23T16:32:46Z

I did it recently on Revise, and it had a happy outcome (with more latency-related news too, timholy/Revise.jl#484 (comment)). Just tried now with ImageView, but held up by JuliaGraphics/Gtk.jl#511.

- `at-nospecialize(a)` syntax was not allowed as a kwarg - include nospecialize annotations in the keyword sorter method - we were dropping nospecialize applied to keyword arguments

…6019) - `at-nospecialize(a)` syntax was not allowed as a kwarg - include nospecialize annotations in the keyword sorter method - we were dropping nospecialize applied to keyword arguments

…ments (JuliaLang#36019) - `at-nospecialize(a)` syntax was not allowed as a kwarg - include nospecialize annotations in the keyword sorter method - we were dropping nospecialize applied to keyword arguments

timholy · 2021-01-10T14:49:10Z

This still doesn't seem quite fixed. On a branch that's pretty close to master,

julia> for m in methods(Base.CoreLogging.handle_message)
           @show m m.nospecialize
       end
m = handle_message(::Base.CoreLogging.NullLogger, args...; kwargs...) in Base.CoreLogging at logging.jl:103
m.nospecialize = 0
m = handle_message(logger::Base.CoreLogging.SimpleLogger, level::Base.CoreLogging.LogLevel, message, _module, group, id, filepath, line; kwargs...) in Base.CoreLogging at logging.jl:637
m.nospecialize = -1
m = handle_message(logger::Logging.ConsoleLogger, level::Base.CoreLogging.LogLevel, message, _module, group, id, filepath, line; kwargs...) in Logging at /home/tim/src/julia-branch/usr/share/julia/stdlib/v1.7/Logging/src/ConsoleLogger.jl:99
m.nospecialize = -1
m = handle_message(logger::Test.TestLogger, level, msg, _module, group, id, file, line; kwargs...) in Test at /home/tim/src/julia-branch/usr/share/julia/stdlib/v1.7/Test/src/logging.jl:41
m.nospecialize = -1
m = handle_message(logger::Revise.ReviseLogger, level, msg, _module, group, id, file, line; kwargs...) in Revise at /home/tim/.julia/dev/Revise/src/logging.jl:26
m.nospecialize = 0

julia> for m in methods(Core.kwfunc(Base.CoreLogging.handle_message))
           @show m m.nospecialize
       end
m = (::Base.CoreLogging.var"#handle_message##kw")(::Any, ::typeof(Base.CoreLogging.handle_message), ::Base.CoreLogging.NullLogger, args...) in Base.CoreLogging at logging.jl:103
m.nospecialize = 0
m = (::Base.CoreLogging.var"#handle_message##kw")(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Base.CoreLogging.SimpleLogger, level::Base.CoreLogging.LogLevel, message, _module, group, id, filepath, line) in Base.CoreLogging at logging.jl:637
m.nospecialize = 0
m = (::Base.CoreLogging.var"#handle_message##kw")(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Logging.ConsoleLogger, level::Base.CoreLogging.LogLevel, message, _module, group, id, filepath, line) in Logging at /home/tim/src/julia-branch/usr/share/julia/stdlib/v1.7/Logging/src/ConsoleLogger.jl:99
m.nospecialize = 0
m = (::Base.CoreLogging.var"#handle_message##kw")(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Test.TestLogger, level, msg, _module, group, id, file, line) in Test at /home/tim/src/julia-branch/usr/share/julia/stdlib/v1.7/Test/src/logging.jl:41
m.nospecialize = 0
m = (::Base.CoreLogging.var"#handle_message##kw")(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Revise.ReviseLogger, level, msg, _module, group, id, file, line) in Revise at /home/tim/.julia/dev/Revise/src/logging.jl:26
m.nospecialize = 0

StefanKarpinski · 2021-04-07T16:20:52Z

Is this still problematic?

vtjnash · 2021-04-08T01:55:32Z

Yes, you can run timholy's commands just above to see the problem

vtjnash · 2021-04-08T01:56:19Z

Possibly similar also to #39902?

vtjnash · 2023-01-24T21:48:30Z

seems addressed now

julia> for m in methods(Core.kwcall, (Any, typeof(Base.CoreLogging.handle_message), Vararg))
           @show m m.nospecialize
       end
m = kwcall(::Any, ::typeof(Base.CoreLogging.handle_message), ::Base.CoreLogging.NullLogger, args...) @ Base.CoreLogging logging.jl:103
m.nospecialize = -1
m = kwcall(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Base.CoreLogging.SimpleLogger, level::Base.CoreLogging.LogLevel, message, _module, group, id, filepath, line) @ Base.CoreLogging logging.jl:664
m.nospecialize = -1
m = kwcall(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Logging.ConsoleLogger, level::Base.CoreLogging.LogLevel, message, _module, group, id, filepath, line) @ Logging /data/vtjnash/julia/usr/share/julia/stdlib/v1.10/Logging/src/ConsoleLogger.jl:106
m.nospecialize = -1
m = kwcall(::Any, ::typeof(Base.CoreLogging.handle_message), logger::Test.TestLogger, level, msg, _module, group, id, file, line) @ Test /data/vtjnash/julia/usr/share/julia/stdlib/v1.10/Test/src/logging.jl:95
m.nospecialize = -1

timholy added the compiler:latency Compiler latency label May 23, 2020

timholy added a commit to JuliaDebug/JuliaInterpreter.jl that referenced this issue May 23, 2020

A few more precompile directives

a80c20a

With progress in eliminating invalidations, these didn't used to help but now they do. xref JuliaLang/julia#34516 (comment)

timholy mentioned this issue May 23, 2020

Move backedge analysis here from Revise, add docs, and release 1.0 JuliaDebug/LoweredCodeUtils.jl#30

Merged

JeffBezanson self-assigned this May 23, 2020

JeffBezanson mentioned this issue May 24, 2020

fix #34516, several issues with nospecialize on keyword arguments #36019

Merged

JeffBezanson closed this as completed in #36019 May 26, 2020

timholy mentioned this issue Oct 20, 2020

precompile seems too picky about unspecialized kwfunc signatures #38095

Open

timholy reopened this Jan 10, 2021

timholy mentioned this issue Jan 10, 2021

Add some costly precompiles #39179

Merged

vtjnash added the compiler:lowering Syntax lowering (compiler front end, 2nd stage) label Apr 8, 2021

vtjnash closed this as completed Jan 24, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

kwfunc drops the nospecialize annotation #34516

kwfunc drops the nospecialize annotation #34516

timholy commented Jan 26, 2020

KristofferC commented Jan 26, 2020 •

edited

Loading

timholy commented May 23, 2020

JeffBezanson commented May 23, 2020

timholy commented May 23, 2020

timholy commented Jan 10, 2021

StefanKarpinski commented Apr 7, 2021

vtjnash commented Apr 8, 2021

vtjnash commented Apr 8, 2021

vtjnash commented Jan 24, 2023

kwfunc drops the nospecialize annotation #34516

kwfunc drops the nospecialize annotation #34516

Comments

timholy commented Jan 26, 2020

KristofferC commented Jan 26, 2020 • edited Loading

timholy commented May 23, 2020

JeffBezanson commented May 23, 2020

timholy commented May 23, 2020

timholy commented Jan 10, 2021

StefanKarpinski commented Apr 7, 2021

vtjnash commented Apr 8, 2021

vtjnash commented Apr 8, 2021

vtjnash commented Jan 24, 2023

KristofferC commented Jan 26, 2020 •

edited

Loading