Add descend_clicked (#211)

Also modifies and expands the README about topics related to
performance-improvement.

Author: timholy

Project.toml

@@ -17,6 +17,7 @@ IntervalSets = "8197267c-284f-5f27-9208-e0e47529a953"
 MethodAnalysis = "85b6ec6f-f7df-4429-9514-a64bcd9ee824"
 Preferences = "21216c6a-2e73-6563-6e65-726566657250"
 Profile = "9abbd945-dff8-562f-b5e8-e1ebf5ef1b79"
+Requires = "ae029012-a4dd-5104-9daa-d747884805df"
 SnoopPrecompile = "66db9d55-30c0-4569-8b51-7e840670fc0c"
 UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4"
 
@@ -31,6 +32,7 @@ GtkObservables = "1"
 IntervalSets = "0.2, 0.3, 0.4, 0.5, 0.6, 0.7"
 MethodAnalysis = "0.4"
 Preferences = "1.2"
+Requires = "1"
 SnoopPrecompile = "1"
 julia = "1.6"
 

README.md

@@ -65,11 +65,11 @@ using ProfileView
 > This is because VSCode defines its own `@profview`, which conflicts with ProfileView's.
 > Fix it by using `ProfileView.@profview`.
 
-If you're following along, you should see something like this:
+If you're following along, you may see something like this:
 
 ![ProfileView](readme_images/pv1.png)
 
-(Note that collected profiles can vary from run-to-run, so don't be alarmed
+(Note that collected profiles can vary by Julia version and from run-to-run, so don't be alarmed
 if you get something different.)
 This plot is a visual representation of the *call graph* of the code that you just profiled.
 The "root" of the tree is at the bottom; if you move your mouse along the long horizontal
@@ -115,19 +115,22 @@ prompt, and so the bottom `eval` call is red.
 Red bars are problematic only when they account for a sizable
 fraction of the top of a call stack, as only in such cases are they likely to be
 the source of a significant performance bottleneck.
-We can see that `mapslices` relies on run-time dispatch;
+In the image above, can see that `mapslices` relied on run-time dispatch;
 from the absence of pastel-colored bars above much of the red, we
-might guess that this makes a substantial
+might guess that this made a substantial
 contribution to its total run time.
-
-To determine the nature of the inference problem(s) in a red bar, left-click on it
-and then enter
-
-```julia
-julia> warntype_last()
-```
-
-at the REPL. You'll see the result of Julia's `code_warntype` for that particular call.
+(Your version of Julia may show different results.)
+See [Solving type-inference problems](solving-type-inference-problems) below
+for tips on how to efficiently diagnose the nature of the problem.
+
+Yellow is also a special color: it indicates a site of garbage collection, which can be
+triggered at a site of memory allocation. You may find that such bars lead you to lines
+whose performance can be improved by reducing the amount of temporary memory allocated
+by your program. One common example is to consider using `@views(A[:, i] .* v)` instead
+of `A[:, i] .* v`; the latter creates a new column-vector from `A`, whereas the former
+just creates a reference to it.
+Julia's [memory profiler](https://docs.julialang.org/en/v1/stdlib/Profile/#Memory-profiling)
+may provide much more information about the usage of memory in your program.
 
 ## GUI features
 
@@ -184,6 +187,81 @@ Some default settings can be changed and retained across settings through a
 **NOTE**: ProfileView does not support the old JLD-based `*.jlprof` files anymore.
 Use the format provided by FlameGraphs v0.2 and higher.
 
+
+## Solving type-inference problems
+
+[Cthulhu.jl](https://github.com/JuliaDebug/Cthulhu.jl) is a powerful tool for
+diagnosing problems of type inference. Let's do a simple demo:
+
+```julia
+function profile_test_sort(n, len=100000)
+    for i = 1:n
+        list = []
+        for _ in 1:len
+            push!(list, rand())
+        end
+        sort!(list)
+    end
+end
+
+julia> profile_test_sort(1)  # to force compilation
+
+julia> @profview profile_test_sort(10)
+```
+
+Notice that there are lots of individual red bars (`sort!` is recursive) along the top
+row of the image. To determine the nature of the inference problem(s) in a red bar, left-click on it
+and then enter
+
+```julia
+julia> using Cthulhu
+
+julia> descend_clicked()
+```
+
+You may see something like this:
+
+![ProfileView](readme_images/descend.png)
+
+You can see the source code of the running method, with "problematic" type-inference
+results highlighted in red. (By default, non-problematic type inference results are
+suppressed, but you can toggle their display with `'h'`.)
+
+For this example, you can see that objects extracted from `v` have type `Any`: that's because in
+`profile_test_sort`, we created `list` as `list = []`, which makes it a `Vector{Any}`;
+in this case, a better option might be `list = Float64[]`. Notice that the *cause* of the performance
+problem is quite far-removed from the place where it manifests, because it's only when
+the low-level operations required by `sort!` get underway that the consequence of our choice
+of container type become an issue. Often it's necessary to "chase" these performance issues
+backwards to a caller; for that, `ascend_clicked()` can be useful:
+
+```julia
+julia> ascend_clicked()
+Choose a call for analysis (q to quit):
+ >   partition!(::Vector{Any}, ::Int64, ::Int64, ::Int64, ::Base.Order.ForwardOrdering, ::Vector{Any}, ::Bool, ::Vector{Any}, ::Int64)
+       #_sort!#25(::Vector{Any}, ::Int64, ::Bool, ::Bool, ::typeof(Base.Sort._sort!), ::Vector{Any}, ::Base.Sort.ScratchQuickSort{Missing, Missing, Base.Sort.Insertio
+         kwcall(::NamedTuple{(:t, :offset, :swap, :rev), Tuple{Vector{Any}, Int64, Bool, Bool}}, ::typeof(Base.Sort._sort!), ::Vector{Any}, ::Base.Sort.ScratchQuickSo
+           #_sort!#25(::Vector{Any}, ::Int64, ::Bool, ::Bool, ::typeof(Base.Sort._sort!), ::Vector{Any}, ::Base.Sort.ScratchQuickSort{Missing, Missing, Base.Sort.Inse
+           #_sort!#25(::Nothing, ::Nothing, ::Bool, ::Bool, ::typeof(Base.Sort._sort!), ::Vector{Any}, ::Base.Sort.ScratchQuickSort{Missing, Missing, Base.Sort.Insert
+             _sort!(::Vector{Any}, ::Base.Sort.ScratchQuickSort{Missing, Missing, Base.Sort.InsertionSortAlg}, ::Base.Order.ForwardOrdering, ::NamedTuple{(:scratch, :
+               _sort!(::Vector{Any}, ::Base.Sort.StableCheckSorted{Base.Sort.ScratchQuickSort{Missing, Missing, Base.Sort.InsertionSortAlg}}, ::Base.Order.ForwardOrde
+                 _sort!(::Vector{Any}, ::Base.Sort.IsUIntMappable{Base.Sort.Small{40, Base.Sort.InsertionSortAlg, Base.Sort.CheckSorted{Base.Sort.ComputeExtrema{Base.
+                   _sort!(::Vector{Any}, ::Base.Sort.IEEEFloatOptimization{Base.Sort.IsUIntMappable{Base.Sort.Small{40, Base.Sort.InsertionSortAlg, Base.Sort.CheckSor
+v                    _sort!(::Vector{Any}, ::Base.Sort.Small{10, Base.Sort.InsertionSortAlg, Base.Sort.IEEEFloatOptimization{Base.Sort.IsUIntMappable{Base.Sort.Small{
+```
+
+This is an interactive menu showing each "callee" above the "caller": use the up and down arrows to pick a call to `descend` into. If you scroll to the bottom
+you'll see the `profile_test_sort` call that triggered the whole cascade.
+
+You can also see type-inference results without using Cthulhu: just enter
+
+```
+julia> warntype_clicked()
+```
+
+at the REPL. You'll see the result of Julia's `code_warntype` for the call you clicked on.
+
+
 ### Advanced usage: deeper analysis of specific dispatches
 
 `ProfileView.clicked[]` stores a stackframe entry for the most recently clicked

readme_images/descend.png

@@ -15,11 +15,13 @@ using Gtk.ShortNames, GtkObservables, Colors, FileIO, IntervalSets
 import Cairo
 using Graphics
 using Preferences
+using Requires
 
 using FlameGraphs: Node, NodeData
 using Gtk.GConstants.GdkModifierType: SHIFT, CONTROL, MOD1
 
-export @profview, warntype_last
+export @profview, warntype_clicked, descend_clicked, ascend_clicked
+@deprecate warntype_last warntype_clicked
 
 const clicked = Ref{Any}(nothing)   # for getting access to the clicked bar
 
@@ -55,14 +57,16 @@ This setting is retained for the active environment via a `LocalPreferences.toml
 set_theme!(theme::Symbol) = set_preference!(_theme, "theme", theme, (:light, :dark))
 
 """
-    warntype_last()
-    warntype_last(io::IO; kwargs...)
+    warntype_clicked()
+    warntype_clicked(io::IO; kwargs...)
 
 Show `code_warntype` for the most recently-clicked bar.
 
 Optionally direct output to stream `io`. Keyword arguments are passed to `code_warntype`.
+
+See also: [`descend_clicked`](@ref).
 """
-function warntype_last(io::IO=stdout; kwargs...)
+function warntype_clicked(io::IO=stdout; kwargs...)
     st = clicked[]
     if st === nothing || st.linfo === nothing
         @warn "click on a non-inlined bar to see `code_warntype` info"
@@ -71,6 +75,30 @@ function warntype_last(io::IO=stdout; kwargs...)
     return code_warntype(io, call_type(st.linfo.specTypes)...; kwargs...)
 end
 
+"""
+    descend_clicked(; optimize=false, iswarn=true, hide_type_stable=true, kwargs...)
+
+Run [Cthulhu's](https://github.com/JuliaDebug/Cthulhu.jl) `descend` for the most recently-clicked bar.
+To make this function available, you must be `using Cthulhu` in your session.
+
+Keyword arguments control the initial view mode.
+
+See also: [`ascend_clicked`](@ref), [`descend_warntype`](@ref)
+"""
+function descend_clicked end
+
+"""
+    ascend_clicked(; hide_type_stable=true, kwargs...)
+
+Run [Cthulhu's](https://github.com/JuliaDebug/Cthulhu.jl) `ascend` for the most recently-clicked bar.
+To make this function available, you must be `using Cthulhu` in your session.
+
+Keyword arguments control the initial view mode.
+
+See also: [`descend_clicked`](@ref)
+"""
+function ascend_clicked end
+
 mutable struct ZoomCanvas
     bb::BoundingBox  # in user-coordinates
     c::Canvas
@@ -489,7 +517,7 @@ end
 
     The toolbar at the top includes icons to load and save profile data. Clicking the save icon will prompt you for a filename; you should use extension *.jlprof for any file you save. Launching `ProfileView.view(nothing)` opens a blank window, which you can populate with saved data by clicking on the "open" icon.
 
-    After clicking on a bar, you can type `warntype_last()` and see the result of `code_warntype` for the call represented by that bar.
+    After clicking on a bar, you can type `warntype_clicked()` and see the result of `code_warntype` for the call represented by that bar. Alterntively, use `descend_clicked` (requires loading Cthulhu.jl).
 
     `ProfileView.view(windowname="method1")` allows you to name your window, which can help avoid confusion when opening several ProfileView windows simultaneously.
 
@@ -506,6 +534,32 @@ end
 discardfirstcol(A) = A[:,2:end]
 discardfirstcol(A::IndirectArray) = IndirectArray(A.index[:,2:end], A.values)
 
+function __init__()
+    @require Cthulhu="f68482b8-f384-11e8-15f7-abe071a5a75f" begin
+        function descend_clicked(; optimize=false, iswarn=true, hide_type_stable=true, kwargs...)
+            st = clicked[]
+            if st === nothing || st.linfo === nothing
+                @warn "the bar you clicked on might have been inlined and unavailable for inspection. Click on a non-inlined bar to `descend`."
+                return nothing
+            end
+            return Cthulhu.descend(st.linfo; optimize, iswarn, hide_type_stable, kwargs...)
+        end
+        function ascend_clicked(; hide_type_stable=true, kwargs...)
+            st = clicked[]
+            if st === nothing || st.linfo === nothing
+                @warn "the bar you clicked on might have been inlined and unavailable for inspection. Click on a non-inlined bar to `descend`."
+                return nothing
+            end
+            return Cthulhu.ascend(st.linfo; hide_type_stable, kwargs...)
+        end
+    end
+    Base.Experimental.register_error_hint(MethodError) do io, exc, argtypes, kwargs
+        if (exc.f === descend_clicked || exc.f === ascend_clicked) && isempty(argtypes)
+            printstyled(io, "\n`using Cthulhu` is required for `$(exc.f)`"; color=:yellow)
+        end
+    end
+end
+
 using SnoopPrecompile
 
 let

src/ProfileView.jl

@@ -161,19 +161,19 @@ end
         ProfileView.closeall()
     end
 
-    @testset "warntype_last" begin
-        # Test `warntype_last`
+    @testset "warntype_clicked" begin
+        # Test `warntype_clicked`
         ProfileView.clicked[] = nothing
-        @test_logs (:warn, "click on a non-inlined bar to see `code_warntype` info") warntype_last() === nothing
+        @test_logs (:warn, "click on a non-inlined bar to see `code_warntype` info") warntype_clicked() === nothing
         _, bt = add2(Any[1,2])
         st = stacktrace(bt)
         ProfileView.clicked[] = st[1]
         io = IOBuffer()
-        warntype_last(io)
+        warntype_clicked(io)
         str = String(take!(io))
         @test occursin("Base.getindex(x, 1)::ANY", str)
         idx = findfirst(sf -> sf.inlined, st)
         ProfileView.clicked[] = st[idx]
-        @test_logs (:warn, "click on a non-inlined bar to see `code_warntype` info") warntype_last(io) === nothing
+        @test_logs (:warn, "click on a non-inlined bar to see `code_warntype` info") warntype_clicked(io) === nothing
     end
 end