JuliaPerf / PProf.jl

Export Julia profiles to the pprof format
MIT License
155 stars 17 forks source link

Fix bug that was skipping inlined functions! #27

Closed NHDaly closed 3 years ago

NHDaly commented 3 years ago

Fix bug that was skipping inlined functions!

We were accidentally skipping registering Function protos for inlined functions, because we were using the frame.pointer to (attempt to) uniquely identify function StackFrames, but actually inlined function StackFrames will actually share the same pointer as the function they were inlined into, since of course all of them are one single frame in practice, and the pointer refers to the Instruction Pointer's position in memory, which will be the same for all the inlined frames and the inlinee.

This meant that the node for a function with other inlined functions was skipping all the inlined functions.

Instead, we need some unique identifier for the function. I'm using the linfo if it's present, and if not I'm using hash((frame.func, frame.file, frame.line)), because at least this will be correct. But I think it might still be overly-unique, because it's possible that multiple lines within the same function will end up registered as different functions. I'm not sure if that matters though?


Here is an example of the problem, and the fix:

julia> @noinline bar(x) = foo(x)
bar (generic function with 1 method)

julia> @inline foo(x) = x+1
foo (generic function with 1 method)

julia> Profile.init(n=Int(1e7), delay=0.0001); Profile.clear()

julia> @profile for i in 1:100_000_000 bar(i) end

julia> pprof(webport=23232)
"profile.pb.gz"

Before:

Screen Shot 2020-09-22 at 7 51 35 PM

After:

Screen Shot 2020-09-22 at 7 50 54 PM
NHDaly commented 3 years ago

Also, it seems to fix some weird duplication of the stack frames that I don't quite understand. :) But we had noticed this too, so i'm glad it's fixed!

EDIT: This is now understood -- see below

vchuravy commented 3 years ago

So the frame.pointer is non-unique? Seems I missunderstoode the format then.

Sacha0 commented 3 years ago

So the frame.pointer is non-unique?

Yes :).

Sacha0 commented 3 years ago

CI failures are confined to a subset of the macOS nightly tests here as well. Not sure whether that's expected?

NHDaly commented 3 years ago

So the frame.pointer is non-unique?

Yes :).

Yeah, from what we can tell they are storing the IP - so it's exactly identical to the keys stored in the data you get back from Profile.fetch(). 👍

NHDaly commented 3 years ago

Also, it seems to fix some weird duplication of the stack frames that I don't quite understand. :) But we had noticed this too, so i'm glad it's fixed!

And, oh, duh, the weird duplication we didn't understand was the inlined frames! I misspoke at the top -- we weren't skipping the frames for inlined functions, we were reporting the inlinee for every inlined frame. So e.g. if at one location you have two frames (one inlined into the other):

2-element Array{Base.StackTraces.StackFrame,1}:
 _jl_invoke at gf.c:2154 [inlined]
 jl_apply_generic at gf.c:2323

We were previously incorrectly reporting both as the second jl_apply_generic frame.

So this explains both the duplication and the missing frames 😁

NHDaly commented 3 years ago

CI failures are confined to a subset of the macOS nightly tests here as well. Not sure whether that's expected?

It wasn't expected but yeah i just confirmed it's failing on master with the latest nightly: https://travis-ci.com/github/JuliaPerf/PProf.jl/builds/186216270

I'll try to push up a fix, separately.

NHDaly commented 3 years ago

Since this is a bug fix, i'm going to merge this and release as a patch release, then i'll release a minor release after merging the (slight) API change in https://github.com/JuliaPerf/PProf.jl/pull/26.