New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
cmd/compile: additional internal debugging support for escape.go #31489
Comments
Seems like it's worthwhile to start discussing this so this can be fixed during Go 1.14. The straightforward solution is to just reimplement esc.go's -m=2 (and above) output, but I've always found that rather difficult to read and understand. Rather than just reimplementing that, I'd like to take a lesson from GOSSAFUNC and consider creating a more visual and interactive interface for viewing the escape analysis graph. For example, I think escape.go could output a JSON (or whatever) description of the escape analysis graphs, including details about all nodes and edges and why they were added to the graph, along with details about escape.go's own analysis results. Then an HTML page could visualize the output, allow focusing on individual escaping locations, identify the paths that caused them to escape, cross-referencing with original source positions, etc. |
Here's a first draft of a JSON-compatible schema for describing escape analysis of a compilation unit.
This is basically just a dump of escape.go's internal details. |
cc @dr2chase, who has been thinking about machine-readable compiler diagnostics. |
In https://github.com/mdempsky/go/tree/escape-debug, I've dumped some rough proof-of-concept code that supports dumping rudimentary escape analysis details as JSON, and then rendering the graph with js.cytoscape.org. Basic usage is:
Current functionality:
Edit: One-click demo: https://escape-debug-demo.web.app/ |
Change https://golang.org/cl/187617 mentions this issue: |
Prep for subsequent CLs to remove old escape analysis pass. This CL removes -newescape=true from tests that use it, and deletes tests that use -newescape=false. (For history, see CL 170447.) Notably, this removes escape_because.go without any replacement, but this is being tracked by #31489. Change-Id: I6f6058d58fff2c5d210cb1d2713200cc9f501ca7 Reviewed-on: https://go-review.googlesource.com/c/go/+/187617 Run-TryBot: Matthew Dempsky <mdempsky@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Robert Griesemer <gri@golang.org>
I am to believe that 1.13 will not contain the same level of information found in 1.12. Specicially this critical information that explains why an escape happened.
|
@ardan-bkennedy Yes, that's what this issue is about. :) esc.go reported those diagnostics, but escape.go does not (yet). |
Thanks to @FiloSottile I learned I can turn off the new escape analysis in 1.13. -gcflags "-newescape=false -m=2" It's enough to get me through the time between now and version 1.14 when this gets fixed. |
Prep for subsequent CLs to remove old escape analysis pass. This CL removes -newescape=true from tests that use it, and deletes tests that use -newescape=false. (For history, see CL 170447.) Notably, this removes escape_because.go without any replacement, but this is being tracked by golang#31489. Change-Id: I6f6058d58fff2c5d210cb1d2713200cc9f501ca7 Reviewed-on: https://go-review.googlesource.com/c/go/+/187617 Run-TryBot: Matthew Dempsky <mdempsky@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Robert Griesemer <gri@golang.org>
Prep for subsequent CLs to remove old escape analysis pass. This CL removes -newescape=true from tests that use it, and deletes tests that use -newescape=false. (For history, see CL 170447.) Notably, this removes escape_because.go without any replacement, but this is being tracked by golang#31489. Change-Id: I6f6058d58fff2c5d210cb1d2713200cc9f501ca7 Reviewed-on: https://go-review.googlesource.com/c/go/+/187617 Run-TryBot: Matthew Dempsky <mdempsky@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Robert Griesemer <gri@golang.org>
Change https://golang.org/cl/196619 mentions this issue: |
Change https://golang.org/cl/196959 mentions this issue: |
CL 196959 restores basic -m=2 diagnostics if folks want to test it out. I'd also appreciate if folks could give constructive feedback on how best to describe escape analysis flows. (I never really became fluent in reading esc.go's diagnostics, which is probably related to why I underestimated their utility to others.) For example, esc.go used to report paths like:
Currently, CL 196959 instead reports that same path as:
My rationale is escape analysis consists of locations and assignments between those locations. The "flows to X" lines indicate each intermediate location where values flow, and the intermediate lines annotate the paths between them. But maybe that's not the mental model that people trying to read the output have, and the same information can be explained more concisely. /cc @FiloSottile |
Here's a slightly different possible description, where the "flows to" lines are represented with assignments using
Is this easier to understand? Are the intermediate lines even useful here? |
Your second one is good (the old version and your first one are both not good), except that I don't quite see why I need the lines that are indented under "flow" (i.e., the intermediate lines). The lines marked "flow" would be even better with some parenthetical mention of the line/column. Users are going to be a little mystified by ~r0 and ~R0. |
To be honest, I've always just followed the line numbers, and guessed at what must be happening. @ardan-bkennedy might have more useful opinions, as he teaches how to read these outputs. |
That’s me as well. I still think some sort of visualization (graphviz?) has a much better chance of being comprehensible than pure text. |
OTYPESW and ORANGE were manually creating locations and flows around them, which are relatively low-level graph construction primitives. This CL changes them to use holes like the rest of the code. Also, introduce "later" as an abstraction for assignment flows that don't happen right away, and which need to prevent expressions from being marked as "transient" (e.g., in ODEFER and ORANGE). There's no behavior change here, but this does reduce the number of newLoc call sites, which should help with restoring -m=2 diagnostics. Passes toolstash-check. Updates #31489. Change-Id: Ic03d4488cb5162afe8b00b12432d203027e8d7d0 Reviewed-on: https://go-review.googlesource.com/c/go/+/196619 Reviewed-by: Cherry Zhang <cherryyz@google.com>
The old output was excellent with the line numbers. It was simple and gave you the exact information needed. It told you what line the construction took place on and what line caused the allocation and the decision as to why. I put this report in my terminal with the list view from the profiler. I can search the report for line numbers and find my answers. This was very effective. The profiler tells me what allocated. This escape analysis report tells me why. For developers like me, anything else is probably noise. |
Thanks for the feedback @ardan-bkennedy. I have some questions to better understand your usage though, if you'll help me out.
Should I infer from this that you think the proposed new output is not excellent with line numbers? If so, can you elaborate why? The 4-space indented lines more-or-less exactly correspond to what the old escape analysis algorithm logged, complete with the same line number details. (There's probably some mismatch, but those can be fixed relatively easily.) The 2-space indented lines summarize the following 4-space indented lines' data flow effect with a single Go-ish assignment syntax. (I'm not attached to this formatting either; just explaining the current working proposal.)
Sorry, I don't think I understand what you mean by "what line caused the allocation." In both of the old and new diagnostics, there are multiple lines of output because all of them acting together caused the heap allocation / parameter leak. Also, when you say "exact information needed", it makes me infer that you care about all of the details that were provided before. E.g., you care about
Can you walk through this process in more detail as a case study? E.g., what information you look for from the profiler, what details you matched it against from the old output and how, and what you then concluded from that? |
Thanks, that's good to know.
Yeah, I don't think they really are (and if we could get rid of them, it would simplify the code substantially). I just don't have a good sense of which details end users care about, so I was trying to be conservative and start with restoring as much of the original details as possible, before working on whittling things back down.
Getting position information for where the assignment actually happens is probably not hard. In complex expressions though, the source operand might appear multiple times in the assignment's RHS, and I think the user wants to know which occurrence is responsible. Unfortunately, we can't do this cleanly today without position information for variable references (since we use the ONAME node directly).
Yeah, doing anything after inlining is a little annoying. :( (And fmt.go doesn't help, since it always prints the pre-inlined form.) I wonder if I can make use of the inlined-from position stack data somehow to make things easier to understand. |
Ack. I'd be happy to help implement the backend of such a visualization, but visualization / UI stuff itself is not my strong point (e.g., my demo web app above). If anyone wants to help with that (by which I mean take lead), it would be greatly appreciated. In the mean time though, I wanted to at least restore the rudimentary trace logs that we used to have for users that depended upon it for performance optimization. (When I removed it, I assumed it was only used by David, Cherry, and others for debugging esc.go; I didn't realize end users made use of it too.) |
Can you generate a report for this test go test -bench . -benchtime 3s -gcflags -m=2 If I can see the report I can tell you if I have what I need to understand these two allocations. |
Done:
|
Looking for everything about stream.go:83 Listing 1 : Actionable
Perfect, I know inlining took place. This is very important since the profiler will NOT show this as a flat allocation since the profiler's list command does not take inlining into account. Which is a real bummer. I need to teach this to explain the reporting. Listing 2 : Actionable
Listing 2 is good. I have found the beginning of the report for line 83 having an allocation. Listing 3 : NOT Actionable
Maybe it's eluding to the fact that when the inlining took place, the Listing 4 : NOT Actionable
Maybe it's validating that Listing 5 : Actionable
This is not as clear as in the old report because of formatting but it is telling me that the allocation is occurring because of line 113. OLD REPORT
In the old report it would tell me that the allocation is because of line 93. Technicall lines 93, 101 or 113 would cause an allocation for the same reason. Why it is not picking up line 93 kind of hurts because technically that the first line of code that causes the allocation in this function. Listing 6 : Actionable
This is giving me the extra information that it the passing of input as a parameter to the Conclusion I can live with this new report since the information is there and searchable based on information I will receive from the profiler. I think it hurts that line 113 is being reported and not line 93. It seems like it's out of order. That being said, It doesn't prevent me from identifying the problem and fixing it. The old report, as I hope you can see, is much clearer and concise about what decisions were made and why. To be complete, this marks the second allocation in the program.
Information is lost here. The reason for this allocation is because the compiler does not know the size of the backing array at compile time. The old report would suggest Conclusion Losing this information hurts and should be provided. A better message like, unknow size or something more clear about that should be provided. |
When there are multiple escaping edges leading to the same escaping, I'm not sure the old code always prints the first one in source order. |
Thanks @ardan-bkennedy! I think that was helpful.
then:
gets processed by inlining into:
The "flow:" lines are walking you through, step-by-step, all of the assignments that eventually lead to the heap. E.g., first there's the assignment "~R0 = &T{}", and then "input = R0", and then the assignment to "io.r" (the temporary variable introduced by inlining to represent io.ReadFull's parameter), and then the assignment to the heap (because io.ReadFull passes r to io.ReadAtLeast, which causes it to escape).
Aside: the current formatting is far from finalized. I'm just dumping out the information currently available until I've had a chance to figure out the best way to present it. If you do happen to have any specific suggestions for better formatting, I'm open to them.
Thanks, I'll look into whether this can be addressed reasonably. I expect at least in simple cases like this we can probably ensure to report line 93 instead of 101 or 113. (I think reporting the last call site here is just an artifact that the new escape analysis algorithm uses a stack to track locations to walk, whereas the old one used a queue IIRC.)
Thanks, I'll restore the original, clearer wording. ("must heap alloc" was just placeholder text anyway.) |
If you think it might help, I could take what you have and play with a new format. At least to something I think may be more friendly to a developer like me. Just to give you different ideas. |
@ardan-bkennedy Yeah, I think that would be helpful to have an idea of how you think the data could be better presented. That said, I've got a couple changes planned that might affect this:
So if you want to wait for those to stabilize before putting in too much effort with a mockup, I'll understand. Also, one question that came up during review of CL 196811: suppose some code like:
We used to report this as:
Those last three lines are basically just repeating the first two (i.e., explaining again that p escapes to heap). Do you think the repetition adds value, or do you think it's okay to omit them and just include a note that For example, what if it instead reported something like:
|
I will wait until I see your new format. I’m my opinion the allocation is occurring because the value is being stored inside the interface at line 7 which has been called an interface-conversion in the past. I am not sure your new format is as clear. IMO, seeing this is all I need.
It’s import line 6 and the p variable is listed since that will correspond to the profile output. Then knowing on line 7 the assignment to the interface value was the cause. |
To be clear, there are two separate allocations here: the
It's this latter allocation that I'm asking about here. In particular, when explaining why
Are these three lines useful to understanding why |
Ohh, I missed the double indirection! Without the double indirection there is only one allocation which is the Given this benchmark
Running the benchmark with this command
Looking at the profile, which is interesting because both allocations are being reported on line 9.
I would say the following: LIne 09 is constructing a value of type Line 10 is assigning the address of Back to the code.
I was super confused with the word Now understanding the code and allocations better. Maybe this is better knowing line 6 will be reported by the profiler.
This is very very hard. I have been thinking about this for 20 minutes. I have no good answers. :( |
Thanks for the feedback, @ardan-bkennedy. That was really helpful. I think my two key takeaways at the moment are:
Yeah, and as far as escape analysis goes, this is actually a rather simple case. :( Not knowing how to explain this case (not to mention the even more complex scenarios we handle) is why I initially hoped to just avoid reimplementing these diagnostics. Anyway, I think at this point I've got some ideas and need to first work on cleaning up the tracing logic in escape.go. Once that's done, I'll ping the issue to get more feedback. |
Hi @mdempsky, I was playing on gotip today and didn't see anything new from this issue. Curious if you have any updates? |
@ardan-bkennedy Sorry, not yet. I'll update the issue when I do. However, I just realized we're approaching the Nov 1 release freeze deadline, and I really do want to get this in for Go 1.14, so thanks for the reminder. |
I updated https://go-review.googlesource.com/c/go/+/196959 to tweak the format to be more like how esc.go used to format it. See CL description for example. It's not identical to the old format, but I think it's close enough that users comfortable with the old format won't find find the new one too jarring. It also still prints the "flow: dst = ***src" summary lines that I think are very helpful for understanding escape analysis behavior. But otherwise, you can always ignore them and just look at the "from" lines. |
This is a rough attempt at restoring -m=2 escape analysis diagnostics on par with those that were available with esc.go. It's meant to be simple and non-invasive. For example, given this random example from bytes/reader.go: 138 func (r *Reader) WriteTo(w io.Writer) (n int64, err error) { ... 143 b := r.s[r.i:] 144 m, err := w.Write(b) esc.go used to report: bytes/reader.go:138:7: leaking param content: r bytes/reader.go:138:7: from r.s (dot of pointer) at bytes/reader.go:143:8 bytes/reader.go:138:7: from b (assigned) at bytes/reader.go:143:4 bytes/reader.go:138:7: from w.Write(b) (parameter to indirect call) at bytes/reader.go:144:19 With this CL, escape.go now reports: bytes/reader.go:138:7: parameter r leaks to {heap} with derefs=1: bytes/reader.go:138:7: flow: b = *r: bytes/reader.go:138:7: from r.s (dot of pointer) at bytes/reader.go:143:8 bytes/reader.go:138:7: from r.s[r.i:] (slice) at bytes/reader.go:143:10 bytes/reader.go:138:7: from b := r.s[r.i:] (assign) at bytes/reader.go:143:4 bytes/reader.go:138:7: flow: {heap} = b: bytes/reader.go:138:7: from w.Write(b) (call parameter) at bytes/reader.go:144:19 Updates #31489. Change-Id: I0c2b943a0f9ce6345bfff61e1c635172a9290cbb Reviewed-on: https://go-review.googlesource.com/c/go/+/196959 Run-TryBot: Matthew Dempsky <mdempsky@google.com> Reviewed-by: David Chase <drchase@google.com>
I looked at the report. I was able to use it for the interface allocation from line 83 in my program. Well Done. It is showing the later call to io.Read but it really doesn't matter. However, you are not explaining the allocation for when I use a variable on the make call. The old report would suggest non-constant size. This new report is providing no indication as to why. |
Change https://golang.org/cl/205917 mentions this issue: |
Thanks, this should be fixed now. |
This CL also restores analysis details for (1) expressions that are directly heap allocated because of being too large for the stack or non-constant in size, and (2) for assignments that we short circuit because we flow their address to another escaping object. No change to normal compilation behavior. Only adds additional Printfs guarded by -m=2. Updates #31489. Change-Id: I43682195d389398d75ced2054e29d9907bb966e7 Reviewed-on: https://go-review.googlesource.com/c/go/+/205917 Run-TryBot: Matthew Dempsky <mdempsky@google.com> Reviewed-by: David Chase <drchase@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org>
Brilliantly Done!
|
Kick-Ass job @mdempsky !! Thanks for all the effort on this. Very much appreciated! |
esc.go and escape.go both support -m=1 for emitting diagnostics about escape analysis results, but esc.go additionally supported -m=2 and above for emitting diagnostics about internal code execution and decision making. escape.go should provide similar functionality for compiler maintainer use.
The text was updated successfully, but these errors were encountered: