pfitzseb / ProfileCanvas.jl

MIT License
87 stars 6 forks source link

Sometimes flames don't merge #16

Closed charleskawczynski closed 2 years ago

charleskawczynski commented 2 years ago

I just tried running ProfileCanvas (really nice looking package, btw!), and I noticed that some of the flames are not merging. Here is an example of a flame graph using ChromeProfileFormat.jl and https://profiler.firefox.com/ vs ProfileCanvas.jl (below). The first issue where this is visible is with the ∑tendencies method, which should be compiled/called for a single set of arguments. update_aux! seems to be another one.

Screen Shot 2022-09-01 at 9 23 18 AM Screen Shot 2022-09-01 at 9 19 36 AM
pfitzseb commented 2 years ago

IIRC merging happens on a line-by-line basis (and judging by the slightly different colors, those are on different lines). Can you upload the HTML somewhere so I can take a look?

charleskawczynski commented 2 years ago

Hmm, I can confirm that there's only one ∑tendencies! definition, but I can upload the html file. Here's a gist

charleskawczynski commented 2 years ago

I’m starting to think that this is a bug in the profiler, I’ll confirm by retrying this with 1.7, and see if I can open an upstream issue so that we can close this

charleskawczynski commented 2 years ago

Strange. On Julia 1.7, using

import ProfileCanvas
ProfileCanvas.view()

and

import PProf
PProf.pprof()

on the same profile results in unmerged flames with ProfileCanvas and merged flames with PProf. However, using

lidict = Profile.getdict(unique(Profile.fetch()))

function get_∑tendencies_frames(lidict)
    stack_frames = []
    for key in keys(lidict)
        for sf in lidict[key]
            if sf.func == :∑tendencies!
                push!(stack_frames, sf)
            end
        end
    end
    return stack_frames
end

get_∑tendencies_frames(lidict)[1].line
get_∑tendencies_frames(lidict)[2].line

in the same session yields

julia> get_∑tendencies_frames(lidict)[1].line
231

julia> get_∑tendencies_frames(lidict)[2].line
223

So it seems like there is a bug in the profiler, or I'm misinterpreting this line field.

charleskawczynski commented 2 years ago

Actually, I think everything is fine. It seems like the discrepancy is actually just that the labels of the flames are slightly different than how PProf organizes them:

I'm fine with closing, unless @pfitzseb has a preference between the two?

charleskawczynski commented 2 years ago

The way PProf labels the flames makes more sense to me, but that's probably just because I've been looking at them for months 😂

charleskawczynski commented 2 years ago

If all of what I said doesn't make sense, then the other way to phrase this is that the multiple ∑tendencies!'s that show up are function calls inside the ∑tendencies! definition.

charleskawczynski commented 2 years ago

Reflecting on this more, I've come to realize that there's an important distinction between the PProf layout and ProfileCanvas layout. ProfileCanvas's layout actually just displays more information than the PProf layout, and the additional information requires a different label scheme, or (you could say) flames seemingly merge less frequently. Take the (modified) test code, for example:

using ProfileCanvas

function foo(A)
    m = maximum(A)
    Am = mapslices(sum, A; dims=2)
    B = A[:,:,5]
    Bsort = mapslices(sort, B; dims=1)
    b = rand(size(A, 1))
    C = B.*b
    return maximum(C)
end

function profile_test(n)
    for i = 1:n
        x = foo(randn(100,100,20))
        x = foo(randn(200,200,20))
        x = foo(randn(40,20,20))
    end
end

@profview profile_test(1)  # run once to trigger compilation (ignore this one)
@profview profile_test(10)

Visualizing this with PProf yields:

Screen Shot 2022-09-04 at 11 03 15 AM

whereas ProfileCanvas yields

Screen Shot 2022-09-04 at 10 56 26 AM

In the PProf version, all foo calls are merged together, and you cannot tell the relative expense of the different foo calls. In ProfileCanvas, you can because they are split up (by line number).

With this information, I think it's fair to close this issue. It's an interesting difference. I think, overall, this is a superior view of the flame graph. It requires a more careful eye as it provides more information at the expense of (potentially) breaking up flames.

Sorry for all the chatter, some of this was just a reminder for future self. Closing.

charleskawczynski commented 2 years ago

For organizational purposes, it might be nice if we could add a flag to (optionally) order of the flames to be alphabetical, so that all of the foo calls are at least grouped together.

charleskawczynski commented 2 years ago

I suppose we could also add a verbosity flag to optionally provide more/less information so that one of them can match PProf's layout

pfitzseb commented 2 years ago

Nice sleuthing! I've opened an issue for those requests :)

FWIW, I'm pretty sure that most of the Julia flame graph visualizers use the same algorithm for display and PProf is the odd one out here.