diff --git a/Project.toml b/Project.toml index 8934faa2..06fc0939 100644 --- a/Project.toml +++ b/Project.toml @@ -7,6 +7,7 @@ version = "2.8.2" Cthulhu = "f68482b8-f384-11e8-15f7-abe071a5a75f" FlameGraphs = "08572546-2f56-4bcf-ba4e-bab62c3a3f89" InteractiveUtils = "b77e0a4c-d291-57a0-90e8-8db25a27a240" +JET = "c3a54625-cd67-489e-a8e7-0a5a0ff4e31b" OrderedCollections = "bac558e1-5e72-5ebc-8fee-abe8a469f55d" Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f" Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7" @@ -19,6 +20,7 @@ YAML = "ddb6d928-2868-570f-bddf-ab3f9cf99eb6" [compat] Cthulhu = "1.5, 2" FlameGraphs = "0.2" +JET = "0.0, 0.4, 0.5" OrderedCollections = "1" Requires = "1" SnoopCompileCore = "~2.8.2" diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl index 6c503d43..3719cf84 100644 --- a/SnoopCompileCore/src/snoopi_deep.jl +++ b/SnoopCompileCore/src/snoopi_deep.jl @@ -123,7 +123,7 @@ See also: `flamegraph`, `flatten`, `inference_triggers`, `SnoopCompile.parcel`, julia> tinf = @snoopi_deep begin sort(rand(100)) # Evaluate some code and profile julia's type inference end -InferenceTimingNode: 0.110018224/0.131464476 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 2 direct children +InferenceTimingNode: 0.110018224/0.131464476 on Core.Compiler.Timings.ROOT() with 2 direct children ``` """ diff --git a/docs/Project.toml b/docs/Project.toml index e12ca690..b51ebbc2 100644 --- a/docs/Project.toml +++ b/docs/Project.toml @@ -1,6 +1,7 @@ [deps] AbstractTrees = "1520ce14-60c1-5f80-bbc7-55ef81b5835c" Documenter = "e30172f5-a6a5-5a46-863b-614d45cd2de4" +JET = "c3a54625-cd67-489e-a8e7-0a5a0ff4e31b" MethodAnalysis = "85b6ec6f-f7df-4429-9514-a64bcd9ee824" PyPlot = "d330b81b-6aea-500a-939a-2ce795aea3ee" diff --git a/docs/make.jl b/docs/make.jl index 4a839f32..3569fe85 100644 --- a/docs/make.jl +++ b/docs/make.jl @@ -11,10 +11,10 @@ makedocs( linkcheck = true, pages = ["index.md", "tutorial.md", - "Modern tools" => ["snoopr.md", "snoopi_deep.md", "pgdsgui.md", "snoopi_deep_analysis.md", "snoopi_deep_parcel.md"], + "Modern tools" => ["snoopr.md", "snoopi_deep.md", "pgdsgui.md", "snoopi_deep_analysis.md", "snoopi_deep_parcel.md", "jet.md"], "Older tools" => ["snoopi.md", "snoopc.md"], "userimg.md", - "reference.md"] + "reference.md"], ) deploydocs( diff --git a/docs/src/index.md b/docs/src/index.md index 47f6545e..6c6fa11f 100644 --- a/docs/src/index.md +++ b/docs/src/index.md @@ -12,6 +12,10 @@ Invalidation can trigger a domino effect, in which all users of invalidated code When a source of invalidation can be identified and either eliminated or mitigated, you can reduce the amount of work that the compiler needs to repeat and take better advantage of precompilation. +Finally, SnoopCompile interacts with other important diagnostics and debugging tools in the Julia ecosystem. +For example, the combination of SnoopCompile and [JET](https://github.com/aviatesk/JET.jl) allows you to analyze an entire call-chain for +potential errors; see the page on [JET integration](@ref JET) for more information. + ## Background Julia uses diff --git a/docs/src/jet.md b/docs/src/jet.md new file mode 100644 index 00000000..156f367f --- /dev/null +++ b/docs/src/jet.md @@ -0,0 +1,133 @@ +# [JET integration](@id JET) + +[JET](https://github.com/aviatesk/JET.jl) is a powerful tool for analyzing call graphs. +While some of its functionality overlaps that of SnoopCompile's, JET also provides mechanisms to detect potential errors. +Conversely, JET is a purely static-analysis tool and lacks SnoopCompile's ability to "bridge" across runtime dispatch. +For this reason, the combination of the tools--using SnoopCompile to collect data on the callgraph, and JET +to perform the error-analysis--provides capabilities that neither package has on its own. + +The integration between the two packages is bundled into SnoopCompile, specifically [`report_callee`](@ref), +[`report_callees`](@ref), and [`report_caller`](@ref). These take [`InferenceTrigger`](@ref) (see the page on [inference failures](@ref inferrability)) and use them to generate JET reports. + +We can demonstrate both the need and use of these tools with a simple extended example. + +## JET usage + +JET provides a useful report for the following call: + +```jldoctest jet; filter=r"@ reduce.*" +julia> using JET + +julia> list = Any[1,2,3]; + +julia> sum(list) +6 + +julia> @report_call sum(list) +═════ 1 possible error found ═════ +┌ @ reducedim.jl:889 Base.#sum#732(Base.:, Base.pairs(Core.NamedTuple()), #self#, a) +│┌ @ reducedim.jl:889 Base._sum(a, dims) +││┌ @ reducedim.jl:893 Base.#_sum#734(Base.pairs(Core.NamedTuple()), #self#, a, _3) +│││┌ @ reducedim.jl:893 Base._sum(Base.identity, a, Base.:) +││││┌ @ reducedim.jl:894 Base.#_sum#735(Base.pairs(Core.NamedTuple()), #self#, f, a, _4) +│││││┌ @ reducedim.jl:894 Base.mapreduce(f, Base.add_sum, a) +││││││┌ @ reducedim.jl:322 Base.#mapreduce#725(Base.:, Base._InitialValue(), #self#, f, op, A) +│││││││┌ @ reducedim.jl:322 Base._mapreduce_dim(f, op, init, A, dims) +││││││││┌ @ reducedim.jl:330 Base._mapreduce(f, op, Base.IndexStyle(A), A) +│││││││││┌ @ reduce.jl:402 Base.mapreduce_empty_iter(f, op, A, Base.IteratorEltype(A)) +││││││││││┌ @ reduce.jl:353 Base.reduce_empty_iter(Base.MappingRF(f, op), itr, ItrEltype) +│││││││││││┌ @ reduce.jl:357 Base.reduce_empty(op, Base.eltype(itr)) +││││││││││││┌ @ reduce.jl:331 Base.mapreduce_empty(Base.getproperty(op, :f), Base.getproperty(op, :rf), _) +│││││││││││││┌ @ reduce.jl:345 Base.reduce_empty(op, T) +││││││││││││││┌ @ reduce.jl:322 Base.reduce_empty(Base.+, _) +│││││││││││││││┌ @ reduce.jl:313 Base.zero(_) +││││││││││││││││┌ @ missing.jl:106 Base.throw(Base.MethodError(Base.zero, Core.tuple(Base.Any))) +│││││││││││││││││ MethodError: no method matching zero(::Type{Any}) +││││││││││││││││└────────────────── +``` + +The final line reveals that while `sum` happened to work for the specific `list` we provided, it nevertheless has a "gotcha" for the types we supplied: if `list` happens to be empty, `sum` depends on the ability to generate `zero(T)` for the element-type `T` of `list`, but because we constructed `list` to have an element-type of `Any`, there is no such method and `sum(Any[])` throws an error: + +```jldoctest +julia> sum(Int[]) +0 + +julia> sum(Any[]) +ERROR: MethodError: no method matching zero(::Type{Any}) +[...] +``` + +(This can be circumvented with `sum(Any[]; init=0)`.) + +This is the kind of bug that can "lurk" undetected for a long time, and JET excels at exposing them. + +## JET limitations + +JET is a *static* analyzer, meaning that it works from the argument types provided, and that has an important consequence: if a particular callee can't be inferred, JET can't analyze it. We can illustrate that quite easily: + +```jldoctest jet +julia> callsum(listcontainer) = sum(listcontainer[1]) +callsum (generic function with 1 method) + +julia> lc = Any[list]; # "hide" `list` inside a Vector{Any} + +julia> callsum(lc) +6 + +julia> @report_call callsum(lc) +No errors ! +``` + +Because we "hid" the type of `list` from inference, JET couldn't tell what specific instance of `sum` was going to be called, so it was unable to detect any errors. + +## JET/SnoopCompile integration + +The resolution to this problem is to use SnoopCompile to do the "data collection" and JET to do the analysis. +The key reason is that SnoopCompile is a dynamic analyzer, and is capable of bridging across runtime dispatch. +As always, you need to do the data collection in a fresh session where the calls have not previously been inferred. +After restarting Julia, we can do this: + +``` +julia> using SnoopCompile + +julia> list = Any[1,2,3]; + +julia> lc = Any[list]; # "hide" `list` inside a Vector{Any} + +julia> callsum(listcontainer) = sum(listcontainer[1]) +callsum (generic function with 1 method) + +julia> tinf = @snoopi_deep callsum(lc) +InferenceTimingNode: 0.039239/0.046793 on Core.Compiler.Timings.ROOT() with 2 direct children + +julia> tinf.children +2-element Vector{SnoopCompileCore.InferenceTimingNode}: + InferenceTimingNode: 0.000869/0.000869 on callsum(::Vector{Any}) with 0 direct children + InferenceTimingNode: 0.000196/0.006685 on sum(::Vector{Any}) with 1 direct children + +julia> report_callees(inference_triggers(tinf)) +1-element Vector{Pair{InferenceTrigger, JET.JETCallResult{JET.JETAnalyzer{JET.BasicPass{typeof(JET.basic_function_filter)}}, Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}}}}: + Inference triggered to call sum(::Vector{Any}) from callsum (./REPL[5]:1) with specialization callsum(::Vector{Any}) => ═════ 1 possible error found ═════ +┌ @ reducedim.jl:889 Base.#sum#732(Base.:, Base.pairs(Core.NamedTuple()), #self#, a) +│┌ @ reducedim.jl:889 Base._sum(a, dims) +││┌ @ reducedim.jl:893 Base.#_sum#734(Base.pairs(Core.NamedTuple()), #self#, a, _3) +│││┌ @ reducedim.jl:893 Base._sum(Base.identity, a, Base.:) +││││┌ @ reducedim.jl:894 Base.#_sum#735(Base.pairs(Core.NamedTuple()), #self#, f, a, _4) +│││││┌ @ reducedim.jl:894 Base.mapreduce(f, Base.add_sum, a) +││││││┌ @ reducedim.jl:322 Base.#mapreduce#725(Base.:, Base._InitialValue(), #self#, f, op, A) +│││││││┌ @ reducedim.jl:322 Base._mapreduce_dim(f, op, init, A, dims) +││││││││┌ @ reducedim.jl:330 Base._mapreduce(f, op, Base.IndexStyle(A), A) +│││││││││┌ @ reduce.jl:402 Base.mapreduce_empty_iter(f, op, A, Base.IteratorEltype(A)) +││││││││││┌ @ reduce.jl:353 Base.reduce_empty_iter(Base.MappingRF(f, op), itr, ItrEltype) +│││││││││││┌ @ reduce.jl:357 Base.reduce_empty(op, Base.eltype(itr)) +││││││││││││┌ @ reduce.jl:331 Base.mapreduce_empty(Base.getproperty(op, :f), Base.getproperty(op, :rf), _) +│││││││││││││┌ @ reduce.jl:345 Base.reduce_empty(op, T) +││││││││││││││┌ @ reduce.jl:322 Base.reduce_empty(Base.+, _) +│││││││││││││││┌ @ reduce.jl:313 Base.zero(_) +││││││││││││││││┌ @ missing.jl:106 Base.throw(Base.MethodError(Base.zero, Core.tuple(Base.Any))) +│││││││││││││││││ MethodError: no method matching zero(::Type{Any}) +││││││││││││││││└────────────────── +``` + +Because SnoopCompile collected the runtime-dispatched `sum` call, we can pass it to JET. +`report_callees` filters those calls which generate JET reports, allowing you to focus on potential errors. diff --git a/docs/src/reference.md b/docs/src/reference.md index ae6264e5..4d5cabd2 100644 --- a/docs/src/reference.md +++ b/docs/src/reference.md @@ -47,6 +47,9 @@ InferenceTrigger runtime_inferencetime SnoopCompile.parcel SnoopCompile.write +report_callee +report_callees +report_caller ``` ## Other utilities diff --git a/docs/src/snoopi_deep.md b/docs/src/snoopi_deep.md index 101f2ed7..31d59d7a 100644 --- a/docs/src/snoopi_deep.md +++ b/docs/src/snoopi_deep.md @@ -118,10 +118,10 @@ You can extract the `MethodInstance` with ```jldoctest flatten-demo julia> Core.MethodInstance(tinf) -MethodInstance for ROOT() +MethodInstance for Core.Compiler.Timings.ROOT() julia> Core.MethodInstance(tinf.children[1]) -MethodInstance for packintype(::Int64) +MethodInstance for FlattenDemo.packintype(::Int64) ``` Each node in this tree is accompanied by a pair of numbers. diff --git a/src/SnoopCompile.jl b/src/SnoopCompile.jl index 8b73be52..1df1079b 100644 --- a/src/SnoopCompile.jl +++ b/src/SnoopCompile.jl @@ -92,6 +92,7 @@ if isdefined(SnoopCompileCore, Symbol("@snoopi_deep")) include("deep_demos.jl") export @snoopi_deep, exclusive, inclusive, flamegraph, flatten, accumulate_by_source, collect_for, runtime_inferencetime, staleinstances export InferenceTrigger, inference_triggers, callerinstance, callingframe, skiphigherorder, trigger_tree, suggest, isignorable + export report_callee, report_caller, report_callees end if isdefined(SnoopCompileCore, Symbol("@snoopl")) diff --git a/src/parcel_snoopi_deep.jl b/src/parcel_snoopi_deep.jl index 02cb431f..663b1905 100644 --- a/src/parcel_snoopi_deep.jl +++ b/src/parcel_snoopi_deep.jl @@ -7,6 +7,7 @@ using Core.Compiler.Timings: InferenceFrameInfo using SnoopCompileCore: InferenceTiming, InferenceTimingNode, inclusive, exclusive using Profile using Cthulhu +using JET const InferenceNode = Union{InferenceFrameInfo,InferenceTiming,InferenceTimingNode} @@ -64,52 +65,52 @@ We'll use [`SnoopCompile.flatten_demo`](@ref), which runs `@snoopi_deep` on a wo ```jldoctest flatten; setup=:(using SnoopCompile), filter=r"([0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?/[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?|WARNING: replacing module FlattenDemo\\.\\n)" julia> tinf = SnoopCompile.flatten_demo() -InferenceTimingNode: 0.002148974/0.002767166 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 1 direct children +InferenceTimingNode: 0.002148974/0.002767166 on Core.Compiler.Timings.ROOT() with 1 direct children julia> using AbstractTrees; print_tree(tinf) -InferenceTimingNode: 0.00242354/0.00303526 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 1 direct children -└─ InferenceTimingNode: 0.000150891/0.000611721 on InferenceFrameInfo for SnoopCompile.FlattenDemo.packintype(::$Int) with 2 direct children - ├─ InferenceTimingNode: 0.000105318/0.000105318 on InferenceFrameInfo for MyType{$Int}(::$Int) with 0 direct children - └─ InferenceTimingNode: 9.43e-5/0.000355512 on InferenceFrameInfo for SnoopCompile.FlattenDemo.dostuff(::MyType{$Int}) with 2 direct children - ├─ InferenceTimingNode: 6.6458e-5/0.000124716 on InferenceFrameInfo for SnoopCompile.FlattenDemo.extract(::MyType{$Int}) with 2 direct children - │ ├─ InferenceTimingNode: 3.401e-5/3.401e-5 on InferenceFrameInfo for getproperty(::MyType{$Int}, ::Symbol) with 0 direct children - │ └─ InferenceTimingNode: 2.4248e-5/2.4248e-5 on InferenceFrameInfo for getproperty(::MyType{$Int}, x::Symbol) with 0 direct children - └─ InferenceTimingNode: 0.000136496/0.000136496 on InferenceFrameInfo for SnoopCompile.FlattenDemo.domath(::$Int) with 0 direct children +InferenceTimingNode: 0.00242354/0.00303526 on Core.Compiler.Timings.ROOT() with 1 direct children +└─ InferenceTimingNode: 0.000150891/0.000611721 on SnoopCompile.FlattenDemo.packintype(::$Int) with 2 direct children + ├─ InferenceTimingNode: 0.000105318/0.000105318 on SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) with 0 direct children + └─ InferenceTimingNode: 9.43e-5/0.000355512 on SnoopCompile.FlattenDemo.dostuff(::SnoopCompile.FlattenDemo.MyType{$Int}) with 2 direct children + ├─ InferenceTimingNode: 6.6458e-5/0.000124716 on SnoopCompile.FlattenDemo.extract(::SnoopCompile.FlattenDemo.MyType{$Int}) with 2 direct children + │ ├─ InferenceTimingNode: 3.401e-5/3.401e-5 on getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, ::Symbol) with 0 direct children + │ └─ InferenceTimingNode: 2.4248e-5/2.4248e-5 on getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, x::Symbol) with 0 direct children + └─ InferenceTimingNode: 0.000136496/0.000136496 on SnoopCompile.FlattenDemo.domath(::$Int) with 0 direct children ``` Note the printing of `getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, x::Symbol)`: it shows the specific Symbol, here `:x`, that `getproperty` was inferred with. This reflects constant-propagation in inference. Then: -```jldoctest flatten; setup=:(using SnoopCompile), filter=r"[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?/[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?" +```jldoctest flatten; setup=:(using SnoopCompile), filter=[r"[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?/[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?", r"WARNING: replacing module FlattenDemo.*"] julia> flatten(tinf; sortby=nothing) 8-element Vector{SnoopCompileCore.InferenceTiming}: - InferenceTiming: 0.002423543/0.0030352639999999998 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() - InferenceTiming: 0.000150891/0.0006117210000000001 on InferenceFrameInfo for SnoopCompile.FlattenDemo.packintype(::$Int) - InferenceTiming: 0.000105318/0.000105318 on InferenceFrameInfo for SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) - InferenceTiming: 9.43e-5/0.00035551200000000005 on InferenceFrameInfo for SnoopCompile.FlattenDemo.dostuff(::SnoopCompile.FlattenDemo.MyType{$Int}) - InferenceTiming: 6.6458e-5/0.000124716 on InferenceFrameInfo for SnoopCompile.FlattenDemo.extract(::SnoopCompile.FlattenDemo.MyType{$Int}) - InferenceTiming: 3.401e-5/3.401e-5 on InferenceFrameInfo for getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, ::Symbol) - InferenceTiming: 2.4248e-5/2.4248e-5 on InferenceFrameInfo for getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, x::Symbol) - InferenceTiming: 0.000136496/0.000136496 on InferenceFrameInfo for SnoopCompile.FlattenDemo.domath(::$Int) + InferenceTiming: 0.002423543/0.0030352639999999998 on Core.Compiler.Timings.ROOT() + InferenceTiming: 0.000150891/0.0006117210000000001 on SnoopCompile.FlattenDemo.packintype(::$Int) + InferenceTiming: 0.000105318/0.000105318 on SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) + InferenceTiming: 9.43e-5/0.00035551200000000005 on SnoopCompile.FlattenDemo.dostuff(::SnoopCompile.FlattenDemo.MyType{$Int}) + InferenceTiming: 6.6458e-5/0.000124716 on SnoopCompile.FlattenDemo.extract(::SnoopCompile.FlattenDemo.MyType{$Int}) + InferenceTiming: 3.401e-5/3.401e-5 on getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, ::Symbol) + InferenceTiming: 2.4248e-5/2.4248e-5 on getproperty(::SnoopCompile.FlattenDemo.MyType{$Int}, x::Symbol) + InferenceTiming: 0.000136496/0.000136496 on SnoopCompile.FlattenDemo.domath(::$Int) ``` ``` julia> flatten(tinf; tmin=1e-4) # sorts by exclusive time (the time before the '/') 4-element Vector{SnoopCompileCore.InferenceTiming}: - InferenceTiming: 0.000105318/0.000105318 on InferenceFrameInfo for SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) - InferenceTiming: 0.000136496/0.000136496 on InferenceFrameInfo for SnoopCompile.FlattenDemo.domath(::$Int) - InferenceTiming: 0.000150891/0.0006117210000000001 on InferenceFrameInfo for SnoopCompile.FlattenDemo.packintype(::$Int) - InferenceTiming: 0.002423543/0.0030352639999999998 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() + InferenceTiming: 0.000105318/0.000105318 on SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) + InferenceTiming: 0.000136496/0.000136496 on SnoopCompile.FlattenDemo.domath(::$Int) + InferenceTiming: 0.000150891/0.0006117210000000001 on SnoopCompile.FlattenDemo.packintype(::$Int) + InferenceTiming: 0.002423543/0.0030352639999999998 on Core.Compiler.Timings.ROOT() julia> flatten(tinf; sortby=inclusive, tmin=1e-4) # sorts by inclusive time (the time after the '/') 6-element Vector{SnoopCompileCore.InferenceTiming}: - InferenceTiming: 0.000105318/0.000105318 on InferenceFrameInfo for SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) - InferenceTiming: 6.6458e-5/0.000124716 on InferenceFrameInfo for SnoopCompile.FlattenDemo.extract(::SnoopCompile.FlattenDemo.MyType{$Int}) - InferenceTiming: 0.000136496/0.000136496 on InferenceFrameInfo for SnoopCompile.FlattenDemo.domath(::$Int) - InferenceTiming: 9.43e-5/0.00035551200000000005 on InferenceFrameInfo for SnoopCompile.FlattenDemo.dostuff(::SnoopCompile.FlattenDemo.MyType{$Int}) - InferenceTiming: 0.000150891/0.0006117210000000001 on InferenceFrameInfo for SnoopCompile.FlattenDemo.packintype(::$Int) - InferenceTiming: 0.002423543/0.0030352639999999998 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() + InferenceTiming: 0.000105318/0.000105318 on SnoopCompile.FlattenDemo.MyType{$Int}(::$Int) + InferenceTiming: 6.6458e-5/0.000124716 on SnoopCompile.FlattenDemo.extract(::SnoopCompile.FlattenDemo.MyType{$Int}) + InferenceTiming: 0.000136496/0.000136496 on SnoopCompile.FlattenDemo.domath(::$Int) + InferenceTiming: 9.43e-5/0.00035551200000000005 on SnoopCompile.FlattenDemo.dostuff(::SnoopCompile.FlattenDemo.MyType{$Int}) + InferenceTiming: 0.000150891/0.0006117210000000001 on SnoopCompile.FlattenDemo.packintype(::$Int) + InferenceTiming: 0.002423543/0.0030352639999999998 on Core.Compiler.Timings.ROOT() ``` As you can see, `sortby` affects not just the order but also the selection of frames; with exclusive times, `dostuff` did @@ -150,7 +151,7 @@ We'll use [`SnoopCompile.flatten_demo`](@ref), which runs `@snoopi_deep` on a wo ```jldoctest accum1; setup=:(using SnoopCompile), filter=r"([0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?|at .*/deep_demos.jl:\\d+|at Base\\.jl:\\d+|at compiler/typeinfer\\.jl:\\d+|WARNING: replacing module FlattenDemo\\.\\n)" julia> tinf = SnoopCompile.flatten_demo() -InferenceTimingNode: 0.002148974/0.002767166 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 1 direct children +InferenceTimingNode: 0.002148974/0.002767166 on Core.Compiler.Timings.ROOT() with 1 direct children julia> accumulate_by_source(flatten(tinf)) 7-element Vector{Tuple{Float64, Union{Method, Core.MethodInstance}}}: @@ -360,7 +361,7 @@ We'll use [`SnoopCompile.itrigs_demo`](@ref), which runs `@snoopi_deep` on a wor ```jldoctest parceltree; setup=:(using SnoopCompile), filter=r"([0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?|WARNING: replacing module ItrigDemo\\.\\n|UInt8|Float64|SnoopCompile\\.ItrigDemo\\.)" julia> tinf = SnoopCompile.itrigs_demo() -InferenceTimingNode: 0.004490576/0.004711168 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 2 direct children +InferenceTimingNode: 0.004490576/0.004711168 on Core.Compiler.Timings.ROOT() with 2 direct children julia> ttot, pcs = SnoopCompile.parcel(tinf); @@ -706,7 +707,7 @@ We'll use [`SnoopCompile.itrigs_demo`](@ref), which runs `@snoopi_deep` on a wor ```jldoctest triggers; setup=:(using SnoopCompile), filter=r"([0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?|.*/deep_demos\\.jl:\\d+|WARNING: replacing module ItrigDemo\\.\\n)" julia> tinf = SnoopCompile.itrigs_demo() -InferenceTimingNode: 0.004490576/0.004711168 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 2 direct children +InferenceTimingNode: 0.004490576/0.004711168 on Core.Compiler.Timings.ROOT() with 2 direct children julia> itrigs = inference_triggers(tinf) 2-element Vector{InferenceTrigger}: @@ -896,6 +897,77 @@ Cthulhu.specTypes(itrig::InferenceTrigger) = Cthulhu.specTypes(Cthulhu.instance( Cthulhu.backedges(itrig::InferenceTrigger) = (itrig.callerframes,) Cthulhu.nextnode(itrig::InferenceTrigger, edge) = (ret = callingframe(itrig); return isempty(ret.callerframes) ? nothing : ret) +""" + report_callee(itrig::InferenceTrigger) + +Return the `JET.report_call` for the callee in `itrig`. +""" +report_callee(itrig::InferenceTrigger; jetconfigs...) = report_call(Cthulhu.specTypes(itrig); jetconfigs...) + +""" + report_caller(itrig::InferenceTrigger) + +Return the `JET.report_call` for the caller in `itrig`. +""" +report_caller(itrig::InferenceTrigger; jetconfigs...) = report_call(Cthulhu.specTypes(callerinstance(itrig)); jetconfigs...) + +""" + report_callees(itrigs) + +Filter `itrigs` for those with a non-passing `JET` report, returning the list of `itrig => report` pairs. + +# Examples + +```jldoctest jetfib; setup=(using SnoopCompile, JET), filter=r"[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?/[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?" +julia> fib(n::Integer) = n ≤ 2 ? n : fib(n-1) + fib(n-2); + +julia> function fib(str::String) + n = length(str) + return fib(m) # error is here + end +fib (generic function with 2 methods) + +julia> fib(::Dict) = 0; fib(::Vector) = 0; + +julia> list = [5, "hello"]; + +julia> mapfib(list) = map(fib, list) +mapfib (generic function with 1 method) + +julia> tinf = @snoopi_deep try mapfib(list) catch end +InferenceTimingNode: 0.049825/0.071476 on Core.Compiler.Timings.ROOT() with 5 direct children + +julia> @report_call mapfib(list) +No errors ! +``` + +JET did not catch the error because the call to `fib` is hidden behind runtime dispatch. +However, when captured by `@snoopi_deep`, we get + +```jldoctest jetfib; filter=[r"@ .*", r"REPL\\[\\d+\\]|none"] +julia> report_callees(inference_triggers(tinf)) +1-element Vector{Pair{InferenceTrigger, JET.JETCallResult{JET.JETAnalyzer{JET.BasicPass{typeof(JET.basic_function_filter)}}, Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}}}}: + Inference triggered to call fib(::String) from iterate (./generator.jl:47) inlined into Base.collect_to!(::Vector{Int64}, ::Base.Generator{Vector{Any}, typeof(fib)}, ::Int64, ::Int64) (./array.jl:782) => ═════ 1 possible error found ═════ +┌ @ none:3 fib(m) +│ variable m is not defined: fib(m) +└────────── +``` +""" +function report_callees(itrigs; jetconfigs...) + function rr(itrig) + rpt = try + report_callee(itrig; jetconfigs...) + catch err + @warn "skipping $itrig due to report_callee error" exception=err + nothing + end + return itrig => rpt + end + hasreport((itrig, report)) = report !== nothing && !isempty(JET.get_reports(report)) + + return [itrigrpt for itrigrpt in map(rr, itrigs) if hasreport(itrigrpt)] +end + filtermod(mod::Module, itrigs::AbstractVector{InferenceTrigger}) = filter(==(mod) ∘ callermodule, itrigs) ### inference trigger trees @@ -1694,7 +1766,7 @@ We'll use [`SnoopCompile.flatten_demo`](@ref), which runs `@snoopi_deep` on a wo ```jldoctest flamegraph; setup=:(using SnoopCompile), filter=r"([0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?/[0-9]*\\.?[0-9]+([eE][-+]?[0-9]+)?|at.*typeinfer\\.jl:\\d+|0:\\d+|WARNING: replacing module FlattenDemo\\.\\n)" julia> tinf = SnoopCompile.flatten_demo() -InferenceTimingNode: 0.002148974/0.002767166 on InferenceFrameInfo for Core.Compiler.Timings.ROOT() with 1 direct children +InferenceTimingNode: 0.002148974/0.002767166 on Core.Compiler.Timings.ROOT() with 1 direct children julia> fg = flamegraph(tinf) Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:75, 0x00, 0:3334431)) diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl index c28bdea0..e4cdbac5 100644 --- a/test/snoopi_deep.jl +++ b/test/snoopi_deep.jl @@ -905,3 +905,18 @@ end end Pkg.activate(cproj) end + +if Base.VERSION >= v"1.7" + @testset "JET integration" begin + f(c) = sum(c[1]) + c = Any[Any[1,2,3]] + tinf = @snoopi_deep f(c) + rpt = SnoopCompile.JET.@report_call f(c) + @test isempty(SnoopCompile.JET.get_reports(rpt)) + itrigs = inference_triggers(tinf) + irpts = report_callees(itrigs) + @test only(irpts).first == last(itrigs) + @test !isempty(SnoopCompile.JET.get_reports(only(irpts).second)) + @test isempty(SnoopCompile.JET.get_reports(report_caller(itrigs[end]))) + end +end