Profile.jl improvements #33190

vtjnash · 2019-09-07T16:41:39Z

This PR comes with a blog post! JuliaLang/www.julialang.org#447

timholy

Based on a somewhat superficial read, I think this is a nice change.

timholy · 2019-09-08T12:35:51Z

base/stacktraces.jl

@@ -98,31 +96,28 @@ end


 """
-    lookup(pointer::Union{Ptr{Cvoid}, UInt}) -> Vector{StackFrame}
+    lookupat(pointer::Union{Ptr{Cvoid}, UInt}) -> Vector{StackFrame}


Is the name change worth it? I could imagine packages calling lookup. Or is this about handling the off-by-one and you're deliberately breaking direct calls here?

Agreed, this change makes me uncomfortable.

timholy · 2019-09-08T12:38:28Z

base/stacktraces.jl

@@ -224,12 +217,12 @@ all frames above the specified function). Primarily used to remove `StackTraces`
 from the `StackTrace` prior to returning it.
 """
 function remove_frames!(stack::StackTrace, name::Symbol)
-    splice!(stack, 1:something(findlast(frame -> frame.func == name, stack), 0))
+    deleteat!(stack, 1:something(findlast(frame -> frame.func == name, stack), 0))


Wow. Suggests this needs a test, no?

They have the same side-effect, splice! just also returns a copy of the deleted values

Oh, right. I was confusing this with our renaming of (un)shift!

timholy · 2019-09-08T12:55:36Z

stdlib/Profile/src/Profile.jl

+                        continue
+                    end
+                end
+            end


Seems like it would be nice to have some way of annotating tree-nodes that got collapsed onto.

Good idea! What would be most useful to track? I think some sort of max and average depth, or other summary statistics?

timholy · 2019-09-08T12:58:58Z

stdlib/Profile/src/Profile.jl

+import Base.StackTraces: lookupat, UNKNOWN, show_spec_linfo, StackFrame
+
+# deprecated functions: use `getdict` instead
+lookup(ip::UInt) = lookupat(convert(Ptr{Cvoid}, ip) - 1)


Is the name change to fix the off-by-one?

Yeah, it's to make it easier for consumers to detect the change, if necessary. And the deprecation here is because it's where ProfileView expected it. OTOH, this would now subtract 2 for ProfileView (since fetch is now already returning "corrected" values), so perhaps I should define const lookup = lookupat? or ProfileView should switch to using getdict sometime before the v1.4 release?

stdlib/Profile/src/Profile.jl

timholy · 2019-09-08T13:03:58Z

stdlib/Profile/src/Profile.jl


 - `noisefloor` -- Limits frames that exceed the heuristic noise floor of the sample (only applies to format `:tree`).
    A suggested value to try for this is 2.0 (the default is 0). This parameter hides samples for which `n <= noisefloor * √N`,
    where `n` is the number of samples on this line, and `N` is the number of samples for the callee.

 - `mincount` -- Limits the printout to only those lines with at least `mincount` occurrences.
+
+ - `recur` -- Controls the recursion handling in `:tree` format. `off` (default) prints the tree as normal. `flat` instead
+    compresses any recursion (by ip), showing the approximate effect of converting any self-recursion into an iterator.


Saying it's "like an iterator" leaves ambiguous the case where f calls g calls h calls f... and one wonders where this chain gets broken.

I think that doesn't really matter (where it gets broken), since the tree should look identical in that case

timholy · 2019-09-08T13:05:46Z

stdlib/Profile/src/Profile.jl

@@ -299,104 +318,113 @@ error_codes = Dict(
 """
    fetch() -> data

-Returns a reference to the internal buffer of backtraces. Note that subsequent operations,
-like [`clear`](@ref), can affect `data` unless you first make a copy. Note that the
+Returns a copy of the buffer of profile backtraces. Note that the


I don't remember why it was this way before, but this seems like a good change.

I assume it was to be zero-copy, but it's just not that useful given all the other work this needs to do, and simpler to be able to pre-process the buffer here.

We have long been doing an off-by-one computation in `lookup`. This is often convenient, but a bit confusing in cases where you then have to then reverse the adjustment for the correction. As we continue working towards more precise profile results, this becomes somewhat more significant. So try to cleanup some accumulated code-cruft around it and in related code.

fix #24189

(as in garbage-collected--these values cannot be used)

Prints the truncated repeating unicode pattern indent_s in tree view for easier visual sighting.

Ensure that text widths remains positive, even when the terminal is too small to fit everything.

Overhead time is the time spent in that function itself. It can also be sorted by it.

Under ragged recursion, the tree profile can be difficult to interpret since it becomes unclear whether time is being spent in the recursion or doing work for the function itself. To separate those effects, we can subtract off the cost of the recursion from the accumulated sum by rearranging the tree to only include the unique (non-recursive) subgraphs. In many cases, this should be similar in effect to re-writting all recursive functions as iterators. This is enabled with the new option :recur \in (:off, :flat, :flatc) for the format=:tree view. Implementing it for the :flat view is left as an exercise for the reader (although it is believed to be much easier).

Previously, we'd double-count any recursive function for each repetition of that function in a stack snapshot. Now we properly account for the time spent in any particular frame by only recording a single count for it per stack snapshot, regardless of how often that frame appeared in that stacktrace due to recursion (and independent of inlining).

c42f

Great cleanup and nice improvements to Profile!

As much as I like this PR in general, the fact that the off-by-one related to the lookup()->lookupat() is exposed at the julia layer makes me really uncomfortable. Surely no user should have to care about the detail of the platform ABI?

According to #33277 (comment), the -1 is also incorrect for some platform ABIs.

c42f · 2019-09-19T00:45:35Z

base/deprecated.jl

-        lkups = StackTraces.lookup(frame)
-        for outer lkup in lkups
+    for ip in bt
+        ip isa Base.InterpreterIP || (ip -= 1) # convert from return stack to call stack (for inlining info)


Great, I think this answers my question at #33277 (comment)

c42f · 2019-09-19T00:49:55Z

base/stacktraces.jl

@@ -98,31 +96,28 @@ end


 """
-    lookup(pointer::Union{Ptr{Cvoid}, UInt}) -> Vector{StackFrame}
+    lookupat(pointer::Union{Ptr{Cvoid}, UInt}) -> Vector{StackFrame}


Agreed, this change makes me uncomfortable.

c42f · 2019-09-19T01:03:47Z

src/julia_internal.h

@@ -626,9 +626,9 @@ typedef int bt_cursor_t;
 // Special marker in backtrace data for encoding interpreter frames
 #define JL_BT_INTERP_FRAME (((uintptr_t)0)-1)
 size_t rec_backtrace(uintptr_t *data, size_t maxsize) JL_NOTSAFEPOINT;
-size_t rec_backtrace_ctx(uintptr_t *data, size_t maxsize, bt_context_t *ctx) JL_NOTSAFEPOINT;
+size_t rec_backtrace_ctx(uintptr_t *data, size_t maxsize, bt_context_t *ctx, int add_interp_frames) JL_NOTSAFEPOINT;


Excellent change. I was thinking about this exact problem (Profile getting confused by- / having overhead from- interpreter frames) while making #33277.

c42f · 2019-09-19T01:08:36Z

src/signals-unix.c

@@ -668,7 +668,7 @@ static void *signal_listener(void *arg)
            if (critical) {
                bt_size += rec_backtrace_ctx(bt_data + bt_size,
                        JL_MAX_BT_SIZE / jl_n_threads - 1,
-                        signal_context);
+                        signal_context, 0);


Over at #33277 I made the critical error printing aware of interpreter frames (printing is marked as JL_NOTSAFEPOINT and passes the static analyzer). So hopefully we could set this 0 to 1 there.

There’s no gc root for that value here

Oh I see, I forgot this version of bt_data is not rooted and other threads may run the GC.

If doexit, we could just stop the world to print this backtrace data because we're about to attempt to abort anyway and a perf hit is the least of our worries?

It's a little extra complexity though.

With return->call address tanslation done inside jl_unw_stepn, there should largely be no need to make this API breaking change, as all backtrace addresses which the user has access to will already be translated and can be passed directly into `StackTraces.lookup()`, as was done previously. There's one possible exception to this rule: If the user were looking up the debug info for a pointer to a C function *not* obtained from a backtrace, they previously would have had to use `StackTraces.lookup(ptr+1)` to "undo" the the `ptr-1` translation that `StackTraces.lookup` used to perform prior to #33190. This seems like an edge case however and probably not worth breaking the API over.

vtjnash mentioned this pull request Sep 7, 2019

blog: quick post about Profiler.jl update work JuliaLang/www.julialang.org#447

Merged

timholy reviewed Sep 8, 2019

View reviewed changes

vtjnash force-pushed the jn/profile-recurflat branch 2 times, most recently from 933713f to 5df21c3 Compare September 10, 2019 22:18

vtjnash added 11 commits September 13, 2019 14:17

StackTrace: remove printf usage [NFC]

83fd034

profile: ensure stop_timer is synchronous

868a15d

fix #24189

Profile: remove garbage values from the profile

21a1465

(as in garbage-collected--these values cannot be used)

Profile: add "pretty" indent characters

fbf25ae

Prints the truncated repeating unicode pattern indent_s in tree view for easier visual sighting.

Profile: properly handle mini-terms

89ddf9a

Ensure that text widths remains positive, even when the terminal is too small to fit everything.

Profile: show overhead time as well as total time

efc625e

Overhead time is the time spent in that function itself. It can also be sorted by it.

Profile: add informational statement on the number of snapshots taken

30b7d35

Profile: show pointers when not collapsing by line number

0002f0a

vtjnash force-pushed the jn/profile-recurflat branch from 5df21c3 to 0002f0a Compare September 13, 2019 18:40

vtjnash merged commit c40a93b into master Sep 17, 2019

delete-merged-branch bot deleted the jn/profile-recurflat branch September 17, 2019 14:29

c42f mentioned this pull request Sep 17, 2019

Make backtrace buffer handling more systematic #33277

Merged

c42f reviewed Sep 19, 2019

View reviewed changes

c42f mentioned this pull request Sep 25, 2019

Clean up return->call address translation for backtraces #33380

Merged

c42f mentioned this pull request Oct 5, 2019

Memory profiler (continuation of #31534) #33467

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Profile.jl improvements #33190

Profile.jl improvements #33190

vtjnash commented Sep 7, 2019 •

edited

Loading

timholy left a comment

timholy Sep 8, 2019

c42f Sep 19, 2019

timholy Sep 8, 2019

vtjnash Sep 9, 2019

timholy Sep 12, 2019

timholy Sep 8, 2019

vtjnash Sep 9, 2019

timholy Sep 8, 2019

vtjnash Sep 9, 2019

timholy Sep 8, 2019

vtjnash Sep 9, 2019

timholy Sep 8, 2019

vtjnash Sep 9, 2019

c42f left a comment •

edited

Loading

c42f Sep 19, 2019

c42f Sep 19, 2019

c42f Sep 19, 2019

c42f Sep 19, 2019

vtjnash Sep 19, 2019

c42f Sep 19, 2019

Profile.jl improvements #33190

Profile.jl improvements #33190

Conversation

vtjnash commented Sep 7, 2019 • edited Loading

timholy left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

c42f left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vtjnash commented Sep 7, 2019 •

edited

Loading

c42f left a comment •

edited

Loading