Expose changes to Julia via `@snoopi_deep` to report timing profile breakdown of _all MethodInstances_ that are inferred during type inference #139

NHDaly · 2020-09-25T21:20:53Z

This builds on JuliaLang/julia#37749 to expose the information through SnoopCompile.

This adds a macro to SnoopCompileCore @snoopi_deep which collects deep timings from Julia's type inference, and adds functions to display the resulting information as a profile.

TODO:

Add a docstring to InferenceFrameInfo in julia

This is a second attempt at #138.

@Snoopi

```julia julia> module M i(x) = x+3 i2(x) = x+2 h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2 g(y::Integer, x) = h(Any[y]) + Int(x) end; WARNING: replacing module M. julia> SnoopCompileCore.@Snoopi begin M.g(2,3.0) end 3-element Vector{Tuple{Float64,Core.MethodInstance,Vector{Pair{Core.MethodInstance,Core.MethodInstance}}}}: (0.00024819374084472656, MethodInstance for i(::Int64), []) (0.0003299713134765625, MethodInstance for i2(::Int64), []) (0.001934051513671875, MethodInstance for g(::Int64, ::Float64), [MethodInstance for g(::Int64, ::Float64) => MethodInstance for h(::Vector{Any}), MethodInstance for h(::Vector{Any}) => MethodInstance for i2(::Integer), MethodInstance for h(::Vector{Any}) => MethodInstance for i(::Integer)]) ```

…alization

@Snoopi

…erly verbose) I _think_ this now does what we want? ```julia julia> module M i(x) = x+5 i2(x) = x+2 h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2 g(y::Integer, x) = h(Any[y]) + Int(x) end; WARNING: replacing module M. julia> out = SnoopCompileCore.@Snoopi begin M.g(2,3.0) end 3-element Vector{Tuple{Float64,Core.MethodInstance,Vector{Pair{Core.MethodInstance,Core.MethodInstance}}}}: (0.00022411346435546875, MethodInstance for i(::Int64), []) (0.00024890899658203125, MethodInstance for i2(::Int64), []) (0.0016169548034667969, MethodInstance for g(::Int64, ::Float64), [MethodInstance for g(::Int64, ::Float64) => MethodInstance for h(::Vector{Any}), MethodInstance for h(::Vector{Any}) => MethodInstance for i2(::Integer), MethodInstance for h(::Vector{Any}) => MethodInstance for i(::Integer)]) julia> SnoopCompile.collect_per_method_inference_timings(out, :(module M i(x) = x+5 i2(x) = x+2 h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2 g(y::Integer, x) = h(Any[y]) + Int(x) end)) Launching new julia process to run commands... done. [ Info: MethodInstance for i(::Int64): total: 0.00022411346435546875 : 0.034790221 Dict{Any,Float64} with 1 entry: Tuple{typeof(i),Int64} => 0.0347902 Launching new julia process to run commands... done. [ Info: MethodInstance for i2(::Int64): total: 0.00024890899658203125 : 0.035098683 Dict{Any,Float64} with 1 entry: Tuple{typeof(i2),Int64} => 0.0350987 Launching new julia process to run commands... done. [ Info: MethodInstance for g(::Int64, ::Float64): total: 0.0016169548034667969 : 0.046937507 Dict{Any,Float64} with 4 entries: Tuple{typeof(i2),Integer} => 0.0110619 Tuple{typeof(h),Vector{Any}} => 0.025103 Tuple{typeof(i),Integer} => 0.00563928 Tuple{typeof(g),Int64,Float64} => 0.00513329 [ Info: Returning merged results: Dict{Any,Float64} with 6 entries: Tuple{typeof(i2),Integer} => 0.0110619 Tuple{typeof(h),Vector{Any}} => 0.025103 Tuple{typeof(i),Integer} => 0.00563928 Tuple{typeof(i2),Int64} => 0.0350987 Tuple{typeof(g),Int64,Float64} => 0.00513329 Tuple{typeof(i),Int64} => 0.0347902 julia> ```

Now working through some more isssues, like not missing edges and deduplicating edges and nodes.

- for more accurate timings, and - prevent stackoverflow

…ference times 😅

… of the graph each time?

Based on c2640ae / JuliaLang/julia@master...NHDaly:nhd-snoopi-inferrable-set--TimerOutputs-profile

… exclusive times! :)

NHDaly · 2020-09-25T21:21:28Z

Early pass at SnoopI per-method-instance deep inference profile:

Make the functions more readable by printing with a pretty-printed function signature instead of a type tuple. Note though that this isn't ideal since the type tuple ends up as the _typeof_ the function, not the function instance. And not all callable objects are singletons, so you cannot safely call instance on it. Instead, we need to adjust the julia source to produce better records.

SnoopCompileCore/src/snoopi.jl

Co-authored-by: Tim Holy <tim.holy@gmail.com>

- src/parcel_snoopi_deep.jl - SnoopCompileCore/src/snoopi_deep.jl - test/snoopi_deep.jl

…ofile

NHDaly · 2020-10-26T14:59:50Z

Could also be something like @snoopi deep=true (similar to @code_warntype optimize=true), but maybe they are different enough that it doesn't make sense to have them behind the same macro.

@KristofferC - sorry i never responded to this. I had the same idea at first, but since this returns an entirely different data structure, and is used with entirely different helper functions, it doesn't seem to make sense to me to put them in the same macro.

NHDaly · 2020-10-26T15:00:33Z

Alright, tests are passing, and I'm finished applying changes! :)

Please let me know what you think about the to_flamegraph / flamegraph message, and then otherwise I think this is good to go! 🎸

timholy · 2020-10-28T08:03:42Z

This looks basically ready to go. The one thing I'd still recommend (but not insist on, if you disagree) is making the "public" methods flamegraph rather than to_flamegraph. Here are the reasons:

there are two ways to think of a flamegraph: (1) a tool for visualizing runtime costs (this does not fit that) (2) a data structure in which parent-child relationships are represented in two dimensions, where the vertical axis represents parentage and the horizontal axis is used to represent a timing dimension (this does fit that).
I think of flamegraph almost as a constructor (there is no FlameGraph type in FlameGraphs, because it's just the root node of a tree), and we have constructors that take very diverse inputs and return the same type of object. For example, Array{Int}(undef, 3) and Array{Int}(1:3) are very different beasts indeed, yet we call them the same thing because they produce the same output type.

If you do agree that it can safely be another method of flamegraph, perhaps we should even consider having SnoopCompile re-export than name. Alternatively, we could just expect users to say using FlameGraphs.

timholy · 2020-10-28T08:05:19Z

Also, PRs like this are a testament to both your own excellent work and Julia's amazing composability: if you deleted all the documentation (no, please don't!) this is a remarkably small PR given the huge gain in functionality. Pretty incredible.

- adds method to `flamegraph()` constructor: `flamegraph(::Timing)`

Fix up docstrings; remove resolved TODO

NHDaly · 2020-10-29T17:00:37Z

Thanks @timholy for the kind words! ❤️

Agreed regarding how amazing it is that we could add such interesting functionality in such small PRs. 😊

Per your suggestion, I've changed to implement flamegraph(), and re-exported it. Thanks!!

I believe this is ready for final review!

timholy

Merge at will!

SnoopCompileCore/src/SnoopCompileCore.jl

src/parcel_snoopi_deep.jl

Co-authored-by: Tim Holy <tim.holy@gmail.com>

NHDaly · 2020-10-29T19:43:03Z

😁 Thanks! :) I don't have merge permissions, so...... Merge at will! 😁

timholy · 2020-10-29T20:38:12Z

I don't have merge permissions

You should have gotten an email about this earlier today...let me know if you can't find it and I'll try to resend.

NHDaly · 2020-10-29T23:29:29Z

Hehe oh, you're right! 😁 Thanks! :) Amazing. Really appreciate it! ✔️ 🥳

Do you have any preference regarding Merge vs Squash? I'm inclined to Squash because there were a lot of commits here.

NHDaly · 2020-10-29T23:32:34Z

Oh, also, I guess I should do a version bump here.

Is this a minor or patch change? (Or major?) I'm inclined to say minor? And do you think it's okay to release both @snoopl (#135) and @snoopi_deep (this PR) in the same new version?

timholy · 2020-10-30T05:23:58Z

Yes to squash, yes to minor bump, yes to bringing both new pieces of functionality out in a single release. Before registering, we might want to work on the Documenter docs a bit to advertise this functionality.

timholy · 2020-11-07T19:18:20Z

I was going to let you do the honors, @NHDaly, but I'm eager to use this. Thanks again!

NHDaly · 2020-11-09T22:34:05Z

Hehe, eep! I'm sorry -- I was excited to do the honors, too, but I felt like it probably needs more documentation, and then I got carried away doing some analyses now that we have these tools instead of writing the docs! 🙈

Thanks for the merge, @timholy! :) I'll try to follow up with docs soon! <3

timholy · 2020-11-09T22:45:19Z

I may be able to help too. Lots going on so it will be a bit back-burner but it's already helping, so let's at least work with it in master.

NHDaly added 19 commits September 11, 2020 15:53

First pass at snoopi collecting the full inferrable set from julia

d19deab

Update to use bool to control julia "collect inference callees" feature

ac15b22

Almost working parcel per_method_instance_timings -- need to fix seri…

9b5f04a

…alization

Fix now that i've disabled my first attempt in julia

bb83243

Got per-method timing working on helper process! :)

faa3eb8

Now working through some more isssues, like not missing edges and deduplicating edges and nodes.

Switch to BFS instead of (recursive) DFS

9e441cd

- for more accurate timings, and - prevent stackoverflow

Fix code_typed() to code_typed_by_type(tt) to ACTUALLY measure in…

4cad634

…ference times 😅

Try randomly shuffling the leaves to get a (hopefully) different walk…

6a62f74

… of the graph each time?

Second attempt at per-method inf timings: TimerOutputs

4820a24

Based on c2640ae / JuliaLang/julia@master...NHDaly:nhd-snoopi-inferrable-set--TimerOutputs-profile

(silly) fixups to get the linfos to print to a string

21bae6d

Fix double-counting, using "$linfo" for timer name

bc20040

Start precompiling the TimerOutputs snoopi approach

b290ec4

Revert changes to SnoopCompile snoopi

d77e22d

Rewrite snoopi on top of custom Core.Compiler.Timings

5b8603a

Add exclusive_timings() to compute and list the per-method-instance…

615b1b6

… exclusive times! :)

Now julia itself reports exclusive times

bc19fed

Add basic flame graph printing for per-method inference timings!

c91c7d2

NHDaly added 5 commits October 1, 2020 17:39

Close "root" timer so root is an accurate measurement as well! :)

95b3fc2

Split out @snoopi_deep: for the per-method-instance snoopi timings

3b34dd6

Get to_flamegraph(::Timing) working! 😁

6c9de36

Update to work with latest version of JuliaLang/julia#37749

fb48e8a

timholy reviewed Oct 10, 2020

View reviewed changes

SnoopCompileCore/src/snoopi.jl Outdated Show resolved Hide resolved

aminya reviewed Oct 10, 2020

View reviewed changes

SnoopCompileCore/src/snoopi.jl Outdated Show resolved Hide resolved

NHDaly added 3 commits October 12, 2020 16:35

Move flatten_times() for at-snoopi_deep to parcel_snoopi.jl

0974619

Reorganized parcel_snoopi.jl

493ae50

Handle Type Tuples that can't be printed to a string

abfc173

NHDaly and others added 4 commits October 26, 2020 10:02

Apply suggestions from code review

bfa969e

Co-authored-by: Tim Holy <tim.holy@gmail.com>

Fix small type stability of range= in _flamegraph_frame()

421593d

Simplify Project.toml: Use FlameGraphs.LeftChildRightSiblingTrees

6d3ff30

Improve docstrings and comments (PR Review suggestions)

74e7f69

NHDaly force-pushed the nhd-snoopi-inferrable-set--TimerOutputs-profile branch 2 times, most recently from 7070c0e to 44d9f2f Compare October 26, 2020 14:47

Split out snoopi_deep into separate, version-guarded files:

4e6b74f

- src/parcel_snoopi_deep.jl - SnoopCompileCore/src/snoopi_deep.jl - test/snoopi_deep.jl

NHDaly force-pushed the nhd-snoopi-inferrable-set--TimerOutputs-profile branch from 44d9f2f to 4e6b74f Compare October 26, 2020 14:48

Merge branch 'master' into nhd-snoopi-inferrable-set--TimerOutputs-pr…

67c447c

…ofile

NHDaly added 3 commits October 28, 2020 11:28

Simplify the logic in SnoopCompile.max_end_time() and add comments

49ce9f2

Change to_flamegraph() to flamegraph()

2723e48

- adds method to `flamegraph()` constructor: `flamegraph(::Timing)`

Remove qualified names from docstring examples

53d6bf8

Fix up docstrings; remove resolved TODO

timholy approved these changes Oct 29, 2020

View reviewed changes

SnoopCompileCore/src/SnoopCompileCore.jl Show resolved Hide resolved

src/parcel_snoopi_deep.jl Outdated Show resolved Hide resolved

Update src/parcel_snoopi_deep.jl

ba358cc

Co-authored-by: Tim Holy <tim.holy@gmail.com>

timholy merged commit 99eab09 into JuliaDebug:master Nov 7, 2020

NHDaly deleted the nhd-snoopi-inferrable-set--TimerOutputs-profile branch November 9, 2020 22:33

timholy mentioned this pull request Dec 7, 2020

Add some nospecialize and a few precompiles JuliaPlots/AbstractPlotting.jl#502

Closed

Expose changes to Julia via @snoopi_deep to report timing profile breakdown of _all MethodInstances_ that are inferred during type inference #139

Expose changes to Julia via @snoopi_deep to report timing profile breakdown of _all MethodInstances_ that are inferred during type inference #139

Uh oh!

Conversation

NHDaly commented Sep 25, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

NHDaly commented Sep 25, 2020

Uh oh!

Uh oh!

Uh oh!

NHDaly commented Oct 26, 2020

Uh oh!

NHDaly commented Oct 26, 2020

Uh oh!

timholy commented Oct 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

timholy commented Oct 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

NHDaly commented Oct 29, 2020

Uh oh!

timholy left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

NHDaly commented Oct 29, 2020

Uh oh!

timholy commented Oct 29, 2020

Uh oh!

NHDaly commented Oct 29, 2020

Uh oh!

NHDaly commented Oct 29, 2020

Uh oh!

timholy commented Oct 30, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

timholy commented Nov 7, 2020

Uh oh!

NHDaly commented Nov 9, 2020

Uh oh!

timholy commented Nov 9, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Expose changes to Julia via `@snoopi_deep` to report timing profile breakdown of _all MethodInstances_ that are inferred during type inference #139

Expose changes to Julia via `@snoopi_deep` to report timing profile breakdown of _all MethodInstances_ that are inferred during type inference #139

NHDaly commented Sep 25, 2020 •

edited

Loading

timholy commented Oct 28, 2020 •

edited

Loading

timholy commented Oct 28, 2020 •

edited

Loading

timholy commented Oct 30, 2020 •

edited

Loading