search

JuliaLang / Pkg.jl

Pkg - Package manager for the Julia programming language
https://pkgdocs.julialang.org
Other
616 stars 258 forks source link

snoopi_deep results, stale instances #3703

Open mkitti opened 9 months ago

mkitti commented 9 months ago

I did some initial investigation with SnoopCompile[Core]. I previously removed the invalidations by moving code to Base.

julia> using SnoopCompileCore

julia> tinf = @snoopi_deep begin
           using Pkg
           Pkg.activate()
       end;
  Activating project at `~/.julia/environments/v1.11`

julia> using SnoopCompile

julia> staleinstances(tinf)
3-element Vector{SnoopCompileCore.InferenceTiming}:
 InferenceTiming: 0.000647/0.000647 on setindex!(::Dict{String, Base.UUID}, ::Base.UUID, ::Any)
 InferenceTiming: 0.000607/0.000607 on setindex!(::Dict{String, Union{String, Vector{String}}}, ::Any, ::Any)
 InferenceTiming: 0.000580/0.000580 on setindex!(::Dict{String, Vector{String}}, ::Vector{String}, ::Any)

julia> using AbstractTrees

julia> print_tree(tinf; maxdepth=1)
InferenceTimingNode: 1.253399/1.482738 on Core.Compiler.Timings.ROOT() with 23 direct children
├─ InferenceTimingNode: 0.000177/0.000177 on normpath(::String, ::String, ::Vararg{String}) with 0 direct children
├─ InferenceTimingNode: 0.000321/0.002068 on getindex(::Dict{Any, Any}, ::Char) with 2 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.002769/0.002974 on repeat(::Char, ::Int64) with 16 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000015/0.000015 on Pkg.Types.read_project_uuid(nothing::Nothing) with 0 direct children
├─ InferenceTimingNode: 0.001517/0.009118 on convert(::Type{Dict{String, Vector{String}}}, ::Dict{String, Any}) with 1 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000434/0.001054 on Base.TOML.try_return_datetime(::Base.TOML.Parser, ::Int64, ::Int64, ::Int64, ::Int64, ::Int64, ::Int64, ::Int64) with 4 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000193/0.000193 on Dates.DateTime(::Int64, ::Int64, ::Int64, ::Int64, ::Int64, ::Int64, ::Int64) with 0 direct children
├─ InferenceTimingNode: 0.000178/0.000662 on Vector{Dates.DateTime}(UndefInitializer()::UndefInitializer, ::Tuple{Int64}) with 1 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000573/0.017074 on maximum(::Vector{Dates.DateTime}) with 1 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000195/0.000195 on Pair(::String, ::Dates.DateTime) with 0 direct children
├─ InferenceTimingNode: 0.000188/0.006052 on map(::Function, ::Vector{Dict{String, Dates.DateTime}}) with 3 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000483/0.000483 on TOML.Internals.Printer.is_array_of_tables(::Vector{Dict{String, Dates.DateTime}}) with 0 direct children
├─ InferenceTimingNode: 0.000210/0.000590 on Core.kwcall(::@NamedTuple{indent::Int64, sorted::Bool, by::typeof(identity)}, ::typeof(invokelatest), ::Any, ::Any, ::Vararg{Any}) with 2 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000406/0.000406 on Core.kwcall(::@NamedTuple{indent::Int64, sorted::Bool, by::typeof(identity)}, print_table::typeof(TOML.Internals.Printer.print_table), nothing::Nothing, ::IOStream, ::Dict{String, Dates.DateTime}, ::Vector{String}) with 0 direct children
├─ InferenceTimingNode: 0.000022/0.000022 on TOML.Internals.Printer.is_array_of_tables(::Dates.DateTime) with 0 direct children
├─ InferenceTimingNode: 0.000559/0.000887 on (::Base.var"#776#777"{FileWatching.Pidfile.var"#2#4"{Base.Filesystem.File}, Timer})() with 1 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.003947/0.009652 on convert(::Type{Dict{String, Union{String, Vector{String}}}}, ::Dict{String, Any}) with 1 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.001995/0.005560 on Base.deepcopy_internal(::Dict{String, Base.UUID}, ::IdDict{Any, Any}) with 9 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.001967/0.143386 on Base.deepcopy_internal(::Dict{String, Union{String, Vector{String}}}, ::IdDict{Any, Any}) with 12 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.001744/0.006304 on Base.deepcopy_internal(::Dict{String, Vector{String}}, ::IdDict{Any, Any}) with 12 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000284/0.007473 on Base.deepcopy_internal(::Tuple{String}, ::IdDict{Any, Any}) with 2 direct children
│  ⋮
│  
├─ InferenceTimingNode: 0.000143/0.004220 on Base.deepcopy_internal(()::Tuple{}, ::IdDict{Any, Any}) with 2 direct children
│  ⋮
│  
└─ InferenceTimingNode: 0.000220/0.010774 on Base.deepcopy_internal(::Tuple{UInt64}, ::IdDict{Any, Any}) with 2 direct children
   ⋮

julia> fg = flamegraph(tinf)julia> fg = flamegraph(tinf)

Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:79, 0x00, 0:1501429050))

julia> using ProfileView

julia> ProfileView.view(fg)

Base.deepcopy_internal is the large teal block below.

image

mkitti commented 9 months ago 
julia> SnoopCompile.flatten(tinf; sortby=inclusive)
476-element Vector{SnoopCompileCore.InferenceTiming}:
 InferenceTiming: 0.000001/0.000001 on convert(::Type{Union{String, Vector{String}}}, ::Union{String, Vector{String}})
 InferenceTiming: 0.000001/0.000001 on LinearIndices(::Tuple{Base.OneTo{Int64}})
 InferenceTiming: 0.000001/0.000001 on LinearIndices(::Tuple{Base.OneTo{Int64}})
 InferenceTiming: 0.000001/0.000001 on LinearIndices(::Tuple{Base.OneTo{Int64}})
 InferenceTiming: 0.000001/0.000001 on GenericMemoryRef(::Memory{String})
 InferenceTiming: 0.000002/0.000002 on LinearIndices(::Tuple{Base.OneTo{Int64}})
 InferenceTiming: 0.000003/0.000003 on Base.Generator(::Base.var"#238#239"{Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}}}, ::UnitRange{Int64})
 InferenceTiming: 0.000003/0.000003 on Base.Generator(::Base.var"#238#239"{Base.var"#974#975"{Tuple{}, IdDict{Any, Any}}}, ::UnitRange{Int64})
 InferenceTiming: 0.000003/0.000003 on valtype(::Type{Dict{String, Vector{String}}})
 InferenceTiming: 0.000004/0.000004 on keytype(::Type{Dict{String, Vector{String}}})
 InferenceTiming: 0.000004/0.000004 on ArgumentError(::LazyString)
 InferenceTiming: 0.000004/0.000004 on getproperty(::Base.Generator{UnitRange{Int64}, Base.var"#238#239"{Base.var"#974#975"{Tuple{String}, IdDict{Any, Any}}}}, iter::Symbol)
 InferenceTiming: 0.000004/0.000004 on keytype(::Type{Dict{String, Union{String, Vector{String}}}})
 InferenceTiming: 0.000004/0.000004 on Base.isbadzero(max::typeof(max), ::Dates.DateTime)
 InferenceTiming: 0.000004/0.000004 on Base.Generator(::Function, ::Vector{Dict{String, Dates.DateTime}})
 InferenceTiming: 0.000004/0.000004 on getproperty(::Base.Generator{UnitRange{Int64}, Base.var"#238#239"{Base.var"#974#975"{Tuple{String}, IdDict{Any, Any}}}}, f::Symbol)
 InferenceTiming: 0.000004/0.000004 on getproperty(::Base.Generator{UnitRange{Int64}, Base.var"#238#239"{Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}}}}, f::Symbol)
 InferenceTiming: 0.000004/0.000004 on getproperty(::Base.Generator{UnitRange{Int64}, Base.var"#238#239"{Base.var"#974#975"{Tuple{String}, IdDict{Any, Any}}}}, f::Symbol)
 InferenceTiming: 0.000004/0.000004 on getproperty(::Base.Generator{UnitRange{Int64}, Base.var"#238#239"{Base.var"#974#975"{Tuple{}, IdDict{Any, Any}}}}, f::Symbol)
 InferenceTiming: 0.000004/0.000004 on (::Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}})(2::Int64)
 InferenceTiming: 0.000004/0.000004 on (::Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}})(2::Int64)
 InferenceTiming: 0.000004/0.000004 on (::Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}})(2::Int64)
 InferenceTiming: 0.000004/0.000004 on getproperty(::Base.Generator{UnitRange{Int64}, Base.var"#238#239"{Base.var"#974#975"{Tuple{}, IdDict{Any, Any}}}}, f::Symbol)
 InferenceTiming: 0.000004/0.000004 on (::Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}})(2::Int64)
 ⋮
 InferenceTiming: 0.001064/0.007251 on ntuple(::Base.var"#974#975"{Tuple{String}, IdDict{Any, Any}}, ::Int64)
 InferenceTiming: 0.000282/0.007682 on Base.deepcopy_internal(::Tuple{String}, ::IdDict{Any, Any})
 InferenceTiming: 0.001826/0.007841 on Dict{String, Vector{String}}(::Dict{String, Any})
 InferenceTiming: 0.000980/0.009039 on Base._ntuple(::Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}}, ::Int64)
 InferenceTiming: 0.001543/0.010806 on ntuple(::Base.var"#974#975"{Tuple{UInt64}, IdDict{Any, Any}}, ::Int64)
 InferenceTiming: 0.003117/0.010958 on convert(::Type{Dict{String, Vector{String}}}, ::Dict{String, Any})
 InferenceTiming: 0.000230/0.011204 on Base.deepcopy_internal(::Tuple{UInt64}, ::IdDict{Any, Any})
 InferenceTiming: 0.001650/0.013674 on Base._mapreduce(identity::typeof(identity), max::typeof(max), IndexLinear()::IndexLinear, ::Vector{Dates.DateTime})
 InferenceTiming: 0.000655/0.014454 on Base._mapreduce_dim(identity::typeof(identity), max::typeof(max), Base._InitialValue()::Base._InitialValue, ::Vector{Dates.DateTime}, Colon()::Colon)
 InferenceTiming: 0.000572/0.015026 on Base.var"#mapreduce#879"(Colon()::Colon, Base._InitialValue()::Base._InitialValue, mapreduce::typeof(mapreduce), identity::typeof(identity), max::typeof(max), ::Vector{Dates.DateTime})
 InferenceTiming: 0.008886/0.015110 on convert(::Type{Dict{String, Union{String, Vector{String}}}}, ::Dict{String, Any})
 InferenceTiming: 0.000584/0.015610 on mapreduce(identity::typeof(identity), max::typeof(max), ::Vector{Dates.DateTime})
 InferenceTiming: 0.000632/0.016242 on Base.var"#_maximum#897"(Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}}()::Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}}, _maximum::typeof(Base._maximum), identity::typeof(identity), ::Vector{Dates.DateTime}, Colon()::Colon)
 InferenceTiming: 0.000593/0.016835 on Base._maximum(identity::typeof(identity), ::Vector{Dates.DateTime}, Colon()::Colon)
 InferenceTiming: 0.000589/0.017424 on Base.var"#_maximum#896"(Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}}()::Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}}, _maximum::typeof(Base._maximum), ::Vector{Dates.DateTime}, Colon()::Colon)
 InferenceTiming: 0.000554/0.017978 on Base._maximum(::Vector{Dates.DateTime}, Colon()::Colon)
 InferenceTiming: 0.000574/0.018552 on Base.var"#maximum#894"(Colon()::Colon, Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}}()::Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}}, maximum::typeof(maximum), ::Vector{Dates.DateTime})
 InferenceTiming: 0.000616/0.019168 on maximum(::Vector{Dates.DateTime})
 InferenceTiming: 0.198520/0.198520 on getindex(::IdDict{Any, Any}, ::Memory{String})
 InferenceTiming: 0.000388/0.201604 on Base.deepcopy_internal(::Memory{String}, ::IdDict{Any, Any})
 InferenceTiming: 0.000513/0.202885 on Base.deepcopy_internal(::MemoryRef{String}, ::IdDict{Any, Any})
 InferenceTiming: 0.000638/0.205187 on Base.deepcopy_internal(::Vector{String}, ::IdDict{Any, Any})
 InferenceTiming: 0.002084/0.212054 on Base.deepcopy_internal(::Dict{String, Union{String, Vector{String}}}, ::IdDict{Any, Any})
 InferenceTiming: 1.228028/1.534484 on Core.Compiler.Timings.ROOT()