cmd/compile: additional internal debugging support for escape.go

[mdempsky]

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.

[mdempsky]

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.

[mdempsky]

Here's a first draft of a JSON-compatible schema for describing escape analysis of a compilation unit.

type Package struct {
    Tool   string   `json:"tool"`  // creator; e.g., "cmd/compile 1.14"
    Files  []string `json:"files"` // source file paths
    Graphs []Graph  `json:"graphs"`
}

type Graph struct {
    Funcs []Func `json:"funcs"`
    Nodes []Node `json:"nodes"`
}

type Func struct {
    Pos     Pos    `json:"pos"`
    Name    string `json:"name"`    // linker name of function
    Params  []int  `json:"params"`  // indices into Graph.Nodes
    Results []int  `json:"results"` // indices into Graph.Nodes
}

type Node struct {
    Pos      Pos    `json:"pos"`
    Name     string `json:"name"` // user friendly description; not necessarily unique
    Func     int    `json:"func"` // index into Graph.Funcs, or -1 for heap
    Incoming []Edge `json:"incoming"`

    LoopDepth int  `json:"loopDepth"`
    Escapes   bool `json:"escapes"`
    Transient bool `json:"transient"`

    // ParamEsc summarizes the shortest dereference path from the
    // Node to the heap (ParamEsc[0]) or result parameter i
    // (ParamEsc[i]). A value of -1 indicates no path.
    ParamEsc []int `json:"paramEsc"`
}

type Edge struct {
    Pos    Pos    `json:"pos"`
    Why    string `json:"why"`    // compiler explanation for this edge
    Source int    `json:"source"` // index into Graph.Nodes

    Derefs int `json:"derefs"` // >= -1
}

type Pos struct {
    File   int `json:"file"`   // index into Package.Files
    Line   int `json:"line"`   // starting at 1
    Column int `json:"column"` // starting at 1 (byte count)
    // TODO(mdempsky): Inlining?
}

This is basically just a dump of escape.go's internal details.

[cherrymui]

cc @dr2chase, who has been thinking about machine-readable compiler diagnostics.

[mdempsky]

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:

# Checkout and build
git clone -b escape-debug https://github.com/mdempsky/go go-escape-debug
cd go-escape-debug/src
./make.bash
export PATH=$PWD/../bin:$PATH

# Build net/http and extract JSON output to http.json
./dump-esc-json.sh net/http > http.json

# Open visualization (http.json is hard coded)
xdg-open analyze.html

Current functionality:

• You can use the select box at the top-left to browse through all the different escape analysis graphs.
• You can drag nodes around to make the graph easier to read.
• You can click on nodes/edges to get details on the right. (Edges don't have position information currently, because it's not yet tracked by escape.go.)
• Red nodes indicate an edge that escapes.
• Edge labels are the number of dereferences associated with the assignment edge; -1 (which indicates an "address-of" operation) are highlighted in blue.

Edit: One-click demo: https://escape-debug-demo.web.app/

[gopherbot]

Change https://golang.org/cl/187617 mentions this issue: test: remove -newescape from regress tests

[ardan-bkennedy]

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.

./stream.go:83:26: &bytes.Buffer literal escapes to heap
./stream.go:83:26:  from ~R0 (assign-pair) at ./stream.go:83:26
./stream.go:83:26:  from input (assigned) at ./stream.go:83:8
./stream.go:83:26:  from input (interface-converted) at ./stream.go:93:26
./stream.go:83:26:  from io.r (assign-pair) at ./stream.go:93:26
./stream.go:83:26:  from io.r (passed to call[argument escapes]) at ./stream.go:93:26

[mdempsky]

@ardan-bkennedy Yes, that's what this issue is about. :) esc.go reported those diagnostics, but escape.go does not (yet).

[ardan-bkennedy]

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.

[gopherbot]

Change https://golang.org/cl/196619 mentions this issue: cmd/compile: cleanup escape graph construction

[gopherbot]

Change https://golang.org/cl/196959 mentions this issue: cmd/compile: restore -m=2 diagnostics

[mdempsky]

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:

encoding/json/stream.go:83:7: leaking param: dec to result ~r0 level=0
encoding/json/stream.go:83:7:        from dec.buf (dot of pointer) at encoding/json/stream.go:84:28
encoding/json/stream.go:83:7:        from bytes.b (assign-pair) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:        from &bytes.Reader literal (struct literal element) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:        from &bytes.Reader literal (pointer literal) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:        from ~R0 (assign-pair) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:        from bytes.NewReader(dec.buf[dec.scanp:]) (interface-converted) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:        from ~r0 (return) at encoding/json/stream.go:84:2

Currently, CL 196959 instead reports that same path as:

encoding/json/stream.go:83:7: parameter dec leaks to ~r0 with derefs=1:
encoding/json/stream.go:83:7:  flows to bytes.b (derefs=1):
encoding/json/stream.go:83:7:    dot of pointer, dec.buf at encoding/json/stream.go:84:28
encoding/json/stream.go:83:7:    slice, dec.buf[dec.scanp:] at encoding/json/stream.go:84:32
encoding/json/stream.go:83:7:    assign-pair, bytes.b = dec.buf[dec.scanp:] at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:  flows to &bytes.Reader literal (derefs=0):
encoding/json/stream.go:83:7:    struct literal element, &bytes.Reader literal at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:  flows to ~R0 (derefs=-1):
encoding/json/stream.go:83:7:    spill, &bytes.Reader literal at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:    assign-pair, ~R0 = &bytes.Reader literal at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:  flows to ~r0 (derefs=0):
encoding/json/stream.go:83:7:    interface-converted, bytes.NewReader(dec.buf[dec.scanp:]) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:    return, return bytes.NewReader(dec.buf[dec.scanp:]) at encoding/json/stream.go:84:2

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

[mdempsky]

Here's a slightly different possible description, where the "flows to" lines are represented with assignments using & and * operators:

encoding/json/stream.go:83:7: parameter dec leaks to ~r0 with derefs=1:
encoding/json/stream.go:83:7:  flow: bytes.b = *dec:
encoding/json/stream.go:83:7:    dot of pointer, dec.buf at encoding/json/stream.go:84:28
encoding/json/stream.go:83:7:    slice, dec.buf[dec.scanp:] at encoding/json/stream.go:84:32
encoding/json/stream.go:83:7:    assign-pair, bytes.b = dec.buf[dec.scanp:] at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:  flow: (storage for &bytes.Reader literal) = bytes.b:
encoding/json/stream.go:83:7:    struct literal element, &bytes.Reader literal at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:  flow: ~R0 = &(storage for &bytes.Reader literal):
encoding/json/stream.go:83:7:    spill, &bytes.Reader literal at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:    assign-pair, ~R0 = &bytes.Reader literal at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:  flow: ~r0 = ~R0:
encoding/json/stream.go:83:7:    interface-converted, bytes.NewReader(dec.buf[dec.scanp:]) at encoding/json/stream.go:84:24
encoding/json/stream.go:83:7:    return, return bytes.NewReader(dec.buf[dec.scanp:]) at encoding/json/stream.go:84:2

Is this easier to understand? Are the intermediate lines even useful here?

[dr2chase]

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.

[FiloSottile]

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.

[josharian]

To be honest, I've always just followed the line numbers, and guessed at what must be happening.

That’s me as well. I still think some sort of visualization (graphviz?) has a much better chance of being comprehensible than pure text.

[ardan-bkennedy]

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.

[mdempsky]

Thanks for the feedback @ardan-bkennedy. I have some questions to better understand your usage though, if you'll help me out.

The old output was excellent with the line numbers.

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.)

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.

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 from dec.buf (dot of pointer) at encoding/json/stream.go:84:28?

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.

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?

[mdempsky]

Your second one is good

Thanks, that's good to know.

I don't quite see why I need the lines that are indented under "flow" (i.e., the intermediate lines).

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.

The lines marked "flow" would be even better with some parenthetical mention of the line/column.

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).

Users are going to be a little mystified by ~r0 and ~R0.

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.

[mdempsky]

I still think some sort of visualization (graphviz?) has a much better chance of being comprehensible than pure text.

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.)

[ardan-bkennedy]

Can you generate a report for this test https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/memcpu

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.

[mdempsky]

Can you generate a report for this test https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/memcpu

Done:

``` $ cd $GOPATH/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu $ go test -bench . -benchtime 3s -gcflags -m=2 ```

``` # github.com/ardanlabs/gotraining/topics/go/profiling/memcpu [github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.test] ./stream.go:40:6: cannot inline assembleInputStream: unhandled op RANGE ./stream.go:50:6: cannot inline assembleOutputStream: unhandled op RANGE ./stream.go:80:6: cannot inline algOne: unhandled op FOR ./stream.go:83:26: inlining call to bytes.NewBuffer func([]byte) *bytes.Buffer { return &bytes.Buffer literal } ./stream.go:93:26: inlining call to io.ReadFull func(io.Reader, []byte) (int, error) { var io..autotmp_4 int; io..autotmp_4 = ; var io..autotmp_5 error; io..autotmp_5 = ; io..autotmp_4, io..autotmp_5 = io.ReadAtLeast(io.r, io.buf, len(io.buf)); return io..autotmp_4, io..autotmp_5 } ./stream.go:101:27: inlining call to io.ReadFull func(io.Reader, []byte) (int, error) { var io..autotmp_4 int; io..autotmp_4 = ; var io..autotmp_5 error; io..autotmp_5 = ; io..autotmp_4, io..autotmp_5 = io.ReadAtLeast(io.r, io.buf, len(io.buf)); return io..autotmp_4, io..autotmp_5 } ./stream.go:109:19: inlining call to bytes.Compare func([]byte, []byte) int { return bytealg.Compare(bytes.a, bytes.b) } ./stream.go:113:28: inlining call to io.ReadFull func(io.Reader, []byte) (int, error) { var io..autotmp_4 int; io..autotmp_4 = ; var io..autotmp_5 error; io..autotmp_5 = ; io..autotmp_4, io..autotmp_5 = io.ReadAtLeast(io.r, io.buf, len(io.buf)); return io..autotmp_4, io..autotmp_5 } ./stream.go:131:6: cannot inline algTwo: unhandled op FOR ./stream.go:134:26: inlining call to bytes.NewReader func([]byte) *bytes.Reader { return &bytes.Reader literal } ./stream.go:145:27: inlining call to bytes.(*Reader).ReadByte method(*bytes.Reader) func() (byte, error) { bytes.r.prevRune = int(-1); if bytes.r.i >= int64(len(bytes.r.s)) { return byte(0), io.EOF }; var bytes.b·4 byte; bytes.b·4 = ; bytes.b·4 = bytes.r.s[bytes.r.i]; bytes.r.i++; return bytes.b·4, nil } ./stream.go:173:20: inlining call to bytes.(*Reader).UnreadByte method(*bytes.Reader) func() error { if bytes.r.i <= int64(0) { return errors.New(string("bytes.Reader.UnreadByte: at beginning of slice")) }; bytes.r.prevRune = int(-1); bytes.r.i--; return nil } ./stream.go:173:20: inlining call to errors.New func(string) error { return error(&errors.errorString literal) } ./stream.go:58:6: cannot inline main: function too complex: cost 806 exceeds budget 80 ./stream.go:66:13: inlining call to fmt.Println func(...interface {}) (int, error) { var fmt..autotmp_3 int; fmt..autotmp_3 = ; var fmt..autotmp_4 error; fmt..autotmp_4 = ; fmt..autotmp_3, fmt..autotmp_4 = fmt.Fprintln(io.Writer(os.Stdout), fmt.a...); return fmt..autotmp_3, fmt..autotmp_4 } ./stream.go:67:14: inlining call to bytes.(*Buffer).Reset method(*bytes.Buffer) func() { bytes.b.buf = bytes.b.buf[:int(0)]; bytes.b.off = int(0); bytes.b.lastRead = bytes.readOp(0) } ./stream.go:69:44: inlining call to bytes.(*Buffer).Bytes method(*bytes.Buffer) func() []byte { return bytes.b.buf[bytes.b.off:] } ./stream.go:69:26: inlining call to bytes.Compare func([]byte, []byte) int { return bytealg.Compare(bytes.a, bytes.b) } ./stream.go:70:98: inlining call to bytes.(*Buffer).Bytes method(*bytes.Buffer) func() []byte { return bytes.b.buf[bytes.b.off:] } ./stream.go:70:12: inlining call to fmt.Printf func(string, ...interface {}) (int, error) { var fmt..autotmp_4 int; fmt..autotmp_4 = ; var fmt..autotmp_5 error; fmt..autotmp_5 = ; fmt..autotmp_4, fmt..autotmp_5 = fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...); return fmt..autotmp_4, fmt..autotmp_5 } ./stream.go:72:13: inlining call to fmt.Println func(...interface {}) (int, error) { var fmt..autotmp_3 int; fmt..autotmp_3 = ; var fmt..autotmp_4 error; fmt..autotmp_4 = ; fmt..autotmp_3, fmt..autotmp_4 = fmt.Fprintln(io.Writer(os.Stdout), fmt.a...); return fmt..autotmp_3, fmt..autotmp_4 } ./stream.go:73:14: inlining call to bytes.(*Buffer).Reset method(*bytes.Buffer) func() { bytes.b.buf = bytes.b.buf[:int(0)]; bytes.b.off = int(0); bytes.b.lastRead = bytes.readOp(0) } ./stream.go:75:43: inlining call to bytes.(*Buffer).Bytes method(*bytes.Buffer) func() []byte { return bytes.b.buf[bytes.b.off:] } ./stream.go:75:25: inlining call to bytes.Compare func([]byte, []byte) int { return bytealg.Compare(bytes.a, bytes.b) } ./stream.go:76:98: inlining call to bytes.(*Buffer).Bytes method(*bytes.Buffer) func() []byte { return bytes.b.buf[bytes.b.off:] } ./stream.go:76:12: inlining call to fmt.Printf func(string, ...interface {}) (int, error) { var fmt..autotmp_4 int; fmt..autotmp_4 = ; var fmt..autotmp_5 error; fmt..autotmp_5 = ; fmt..autotmp_4, fmt..autotmp_5 = fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...); return fmt..autotmp_4, fmt..autotmp_5 } ./stream_test.go:15:6: cannot inline BenchmarkAlgorithmOne: unhandled op FOR ./stream_test.go:24:15: inlining call to bytes.(*Buffer).Reset method(*bytes.Buffer) func() { bytes.b.buf = bytes.b.buf[:int(0)]; bytes.b.off = int(0); bytes.b.lastRead = bytes.readOp(0) } ./stream_test.go:30:6: cannot inline BenchmarkAlgorithmTwo: unhandled op FOR ./stream_test.go:39:15: inlining call to bytes.(*Buffer).Reset method(*bytes.Buffer) func() { bytes.b.buf = bytes.b.buf[:int(0)]; bytes.b.off = int(0); bytes.b.lastRead = bytes.readOp(0) } ./stream.go:83:26: &bytes.Buffer literal escapes to heap: ./stream.go:83:26: flow: ~R0 = &(temp for &bytes.Buffer literal): ./stream.go:83:26: spill, &bytes.Buffer literal at ./stream.go:83:26 ./stream.go:83:26: assign-pair, ~R0 = &bytes.Buffer literal at ./stream.go:83:26 ./stream.go:83:26: flow: input = ~R0: ./stream.go:83:26: assign, input := (*bytes.Buffer)(~R0) at ./stream.go:83:8 ./stream.go:83:26: flow: io.r = input: ./stream.go:83:26: interface-converted, input at ./stream.go:113:28 ./stream.go:83:26: assign-pair, io.r, io.buf = input, buf[:end] at ./stream.go:113:28 ./stream.go:83:26: flow: heap = io.r: ./stream.go:83:26: call parameter, io.ReadAtLeast(io.r, io.buf, len(io.buf)) at ./stream.go:113:28 ./stream.go:80:13: parameter data leaks to with derefs=0: ./stream.go:80:13: flow: bytes.buf = data: ./stream.go:80:13: assign-pair, bytes.buf = data at ./stream.go:83:26 ./stream.go:80:13: flow: (temp for &bytes.Buffer literal) = bytes.buf: ./stream.go:80:13: struct literal element, &bytes.Buffer literal at ./stream.go:83:26 ./stream.go:80:13: flow: ~R0 = &(temp for &bytes.Buffer literal): ./stream.go:80:13: spill, &bytes.Buffer literal at ./stream.go:83:26 ./stream.go:80:13: assign-pair, ~R0 = &bytes.Buffer literal at ./stream.go:83:26 ./stream.go:80:13: flow: input = ~R0: ./stream.go:80:13: assign, input := (*bytes.Buffer)(~R0) at ./stream.go:83:8 ./stream.go:80:13: flow: io.r = input: ./stream.go:80:13: interface-converted, input at ./stream.go:113:28 ./stream.go:80:13: assign-pair, io.r, io.buf = input, buf[:end] at ./stream.go:113:28 ./stream.go:80:13: flow: heap = io.r: ./stream.go:80:13: call parameter, io.ReadAtLeast(io.r, io.buf, len(io.buf)) at ./stream.go:113:28 ./stream.go:89:13: make([]byte, size) escapes to heap: ./stream.go:89:13: flow: heap = &(temp for make([]byte, size)): ./stream.go:89:13: must heap alloc, make([]byte, size) at ./stream.go:89:13 ./stream.go:80:13: leaking param: data ./stream.go:80:26: find does not escape ./stream.go:80:39: repl does not escape ./stream.go:80:52: output does not escape ./stream.go:83:26: &bytes.Buffer literal escapes to heap ./stream.go:89:13: make([]byte, size) escapes to heap ./stream.go:131:13: data does not escape ./stream.go:131:26: find does not escape ./stream.go:131:39: repl does not escape ./stream.go:131:52: output does not escape ./stream.go:134:26: &bytes.Reader literal does not escape ./stream.go:173:20: &errors.errorString literal does not escape ./stream.go:67:14: main ignoring self-assignment in bytes.b.buf = bytes.b.buf[:int(0)] ./stream.go:73:14: main ignoring self-assignment in bytes.b.buf = bytes.b.buf[:int(0)] ./stream.go:76:98: output.Bytes() escapes to heap: ./stream.go:76:98: flow: ~arg4 = &(temp for output.Bytes()): ./stream.go:76:98: spill, output.Bytes() at ./stream.go:76:98 ./stream.go:76:98: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:76:12 ./stream.go:76:98: flow: (temp for []interface {} literal) = ~arg4: ./stream.go:76:98: slice-literal-element, []interface {} literal at ./stream.go:76:12 ./stream.go:76:98: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:76:98: spill, []interface {} literal at ./stream.go:76:12 ./stream.go:76:98: assign, fmt.a = []interface {} literal at ./stream.go:76:12 ./stream.go:76:98: flow: heap = *fmt.a: ./stream.go:76:98: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:76:12 ./stream.go:76:71: out escapes to heap: ./stream.go:76:71: flow: ~arg3 = &(temp for out): ./stream.go:76:71: spill, out at ./stream.go:76:71 ./stream.go:76:71: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:76:12 ./stream.go:76:71: flow: (temp for []interface {} literal) = ~arg3: ./stream.go:76:71: slice-literal-element, []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:76:71: spill, []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: assign, fmt.a = []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: flow: heap = *fmt.a: ./stream.go:76:71: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:76:12 ./stream.go:76:71: in escapes to heap: ./stream.go:76:71: flow: ~arg2 = &(temp for in): ./stream.go:76:71: spill, in at ./stream.go:76:71 ./stream.go:76:71: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:76:12 ./stream.go:76:71: flow: (temp for []interface {} literal) = ~arg2: ./stream.go:76:71: slice-literal-element, []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:76:71: spill, []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: assign, fmt.a = []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: flow: heap = *fmt.a: ./stream.go:76:71: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:76:12 ./stream.go:76:71: matched == 0 escapes to heap: ./stream.go:76:71: flow: ~arg1 = &(temp for matched == 0): ./stream.go:76:71: spill, matched == 0 at ./stream.go:76:71 ./stream.go:76:71: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:76:12 ./stream.go:76:71: flow: (temp for []interface {} literal) = ~arg1: ./stream.go:76:71: slice-literal-element, []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:76:71: spill, []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: assign, fmt.a = []interface {} literal at ./stream.go:76:12 ./stream.go:76:71: flow: heap = *fmt.a: ./stream.go:76:71: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:76:12 ./stream.go:72:14: "=======================================\nRunning Algorithm Two" escapes to heap: ./stream.go:72:14: flow: ~arg0 = &(temp for "=======================================\nRunning Algorithm Two"): ./stream.go:72:14: spill, "=======================================\nRunning Algorithm Two" at ./stream.go:72:14 ./stream.go:72:14: assign-pair, ~arg0 = "=======================================\nRunning Algorithm Two" at ./stream.go:72:13 ./stream.go:72:14: flow: (temp for []interface {} literal) = ~arg0: ./stream.go:72:14: slice-literal-element, []interface {} literal at ./stream.go:72:13 ./stream.go:72:14: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:72:14: spill, []interface {} literal at ./stream.go:72:13 ./stream.go:72:14: assign, fmt.a = []interface {} literal at ./stream.go:72:13 ./stream.go:72:14: flow: heap = *fmt.a: ./stream.go:72:14: call parameter, fmt.Fprintln(io.Writer(os.Stdout), fmt.a...) at ./stream.go:72:13 ./stream.go:70:98: output.Bytes() escapes to heap: ./stream.go:70:98: flow: ~arg4 = &(temp for output.Bytes()): ./stream.go:70:98: spill, output.Bytes() at ./stream.go:70:98 ./stream.go:70:98: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:70:12 ./stream.go:70:98: flow: (temp for []interface {} literal) = ~arg4: ./stream.go:70:98: slice-literal-element, []interface {} literal at ./stream.go:70:12 ./stream.go:70:98: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:70:98: spill, []interface {} literal at ./stream.go:70:12 ./stream.go:70:98: assign, fmt.a = []interface {} literal at ./stream.go:70:12 ./stream.go:70:98: flow: heap = *fmt.a: ./stream.go:70:98: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:70:12 ./stream.go:70:71: out escapes to heap: ./stream.go:70:71: flow: ~arg3 = &(temp for out): ./stream.go:70:71: spill, out at ./stream.go:70:71 ./stream.go:70:71: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:70:12 ./stream.go:70:71: flow: (temp for []interface {} literal) = ~arg3: ./stream.go:70:71: slice-literal-element, []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:70:71: spill, []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: assign, fmt.a = []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: flow: heap = *fmt.a: ./stream.go:70:71: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:70:12 ./stream.go:70:71: in escapes to heap: ./stream.go:70:71: flow: ~arg2 = &(temp for in): ./stream.go:70:71: spill, in at ./stream.go:70:71 ./stream.go:70:71: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:70:12 ./stream.go:70:71: flow: (temp for []interface {} literal) = ~arg2: ./stream.go:70:71: slice-literal-element, []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:70:71: spill, []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: assign, fmt.a = []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: flow: heap = *fmt.a: ./stream.go:70:71: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:70:12 ./stream.go:70:71: matched == 0 escapes to heap: ./stream.go:70:71: flow: ~arg1 = &(temp for matched == 0): ./stream.go:70:71: spill, matched == 0 at ./stream.go:70:71 ./stream.go:70:71: assign-pair, fmt.format, ~arg1, ~arg2, ~arg3, ~arg4 = "Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes() at ./stream.go:70:12 ./stream.go:70:71: flow: (temp for []interface {} literal) = ~arg1: ./stream.go:70:71: slice-literal-element, []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:70:71: spill, []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: assign, fmt.a = []interface {} literal at ./stream.go:70:12 ./stream.go:70:71: flow: heap = *fmt.a: ./stream.go:70:71: call parameter, fmt.Fprintf(io.Writer(os.Stdout), fmt.format, fmt.a...) at ./stream.go:70:12 ./stream.go:66:14: "=======================================\nRunning Algorithm One" escapes to heap: ./stream.go:66:14: flow: ~arg0 = &(temp for "=======================================\nRunning Algorithm One"): ./stream.go:66:14: spill, "=======================================\nRunning Algorithm One" at ./stream.go:66:14 ./stream.go:66:14: assign-pair, ~arg0 = "=======================================\nRunning Algorithm One" at ./stream.go:66:13 ./stream.go:66:14: flow: (temp for []interface {} literal) = ~arg0: ./stream.go:66:14: slice-literal-element, []interface {} literal at ./stream.go:66:13 ./stream.go:66:14: flow: fmt.a = &(temp for []interface {} literal): ./stream.go:66:14: spill, []interface {} literal at ./stream.go:66:13 ./stream.go:66:14: assign, fmt.a = []interface {} literal at ./stream.go:66:13 ./stream.go:66:14: flow: heap = *fmt.a: ./stream.go:66:14: call parameter, fmt.Fprintln(io.Writer(os.Stdout), fmt.a...) at ./stream.go:66:13 ./stream.go:63:16: ([]byte)("elvis") does not escape ./stream.go:64:16: ([]byte)("Elvis") does not escape ./stream.go:66:14: "=======================================\nRunning Algorithm One" escapes to heap ./stream.go:66:13: []interface {} literal does not escape ./stream.go:70:71: matched == 0 escapes to heap ./stream.go:70:71: in escapes to heap ./stream.go:70:71: out escapes to heap ./stream.go:70:98: output.Bytes() escapes to heap ./stream.go:70:12: []interface {} literal does not escape ./stream.go:72:14: "=======================================\nRunning Algorithm Two" escapes to heap ./stream.go:72:13: []interface {} literal does not escape ./stream.go:76:71: matched == 0 escapes to heap ./stream.go:76:71: in escapes to heap ./stream.go:76:71: out escapes to heap ./stream.go:76:98: output.Bytes() escapes to heap ./stream.go:76:12: []interface {} literal does not escape ./stream_test.go:24:15: BenchmarkAlgorithmOne ignoring self-assignment in bytes.b.buf = bytes.b.buf[:int(0)] ./stream_test.go:15:28: b does not escape ./stream_test.go:18:16: ([]byte)("elvis") does not escape ./stream_test.go:19:16: ([]byte)("Elvis") does not escape ./stream_test.go:39:15: BenchmarkAlgorithmTwo ignoring self-assignment in bytes.b.buf = bytes.b.buf[:int(0)] ./stream_test.go:30:28: b does not escape ./stream_test.go:33:16: ([]byte)("elvis") does not escape ./stream_test.go:34:16: ([]byte)("Elvis") does not escape :1: parameter .this leaks to with derefs=0: :1: flow: heap = .this: :1: call parameter, .this.Error() at :1 :1: leaking param: .this :1: .this does not escape # github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.test /tmp/go-build189039928/b001/_testmain.go:36:6: can inline init.0 as: func() { testdeps.ImportPath = "github.com/ardanlabs/gotraining/topics/go/profiling/memcpu" } /tmp/go-build189039928/b001/_testmain.go:42:6: cannot inline main: function too complex: cost 200 exceeds budget 80 /tmp/go-build189039928/b001/_testmain.go:44:24: inlining call to testing.MainStart func(testing.testDeps, []testing.InternalTest, []testing.InternalBenchmark, []testing.InternalExample) *testing.M { testing.Init(); return &testing.M literal } /tmp/go-build189039928/b001/_testmain.go:44:24: &testing.M literal escapes to heap: /tmp/go-build189039928/b001/_testmain.go:44:24: flow: ~R0 = &(temp for &testing.M literal): /tmp/go-build189039928/b001/_testmain.go:44:24: spill, &testing.M literal at $WORK/b001/_testmain.go:44:24 /tmp/go-build189039928/b001/_testmain.go:44:24: assign-pair, ~R0 = &testing.M literal at $WORK/b001/_testmain.go:44:24 /tmp/go-build189039928/b001/_testmain.go:44:24: flow: m = ~R0: /tmp/go-build189039928/b001/_testmain.go:44:24: assign, m := (*testing.M)(~R0) at $WORK/b001/_testmain.go:44:4 /tmp/go-build189039928/b001/_testmain.go:44:24: flow: heap = m: /tmp/go-build189039928/b001/_testmain.go:44:24: call parameter, m.Run() at $WORK/b001/_testmain.go:46:15 /tmp/go-build189039928/b001/_testmain.go:44:42: testdeps.TestDeps literal escapes to heap: /tmp/go-build189039928/b001/_testmain.go:44:42: flow: testing.deps = &(temp for testdeps.TestDeps literal): /tmp/go-build189039928/b001/_testmain.go:44:42: spill, testdeps.TestDeps literal at $WORK/b001/_testmain.go:44:42 /tmp/go-build189039928/b001/_testmain.go:44:42: assign-pair, testing.deps, testing.tests, testing.benchmarks, testing.examples = testdeps.TestDeps literal, tests, benchmarks, examples at $WORK/b001/_testmain.go:44:24 /tmp/go-build189039928/b001/_testmain.go:44:42: flow: (temp for &testing.M literal) = testing.deps: /tmp/go-build189039928/b001/_testmain.go:44:42: struct literal element, &testing.M literal at $WORK/b001/_testmain.go:44:24 /tmp/go-build189039928/b001/_testmain.go:44:42: flow: ~R0 = &(temp for &testing.M literal): /tmp/go-build189039928/b001/_testmain.go:44:42: spill, &testing.M literal at $WORK/b001/_testmain.go:44:24 /tmp/go-build189039928/b001/_testmain.go:44:42: assign-pair, ~R0 = &testing.M literal at $WORK/b001/_testmain.go:44:24 /tmp/go-build189039928/b001/_testmain.go:44:42: flow: m = ~R0: /tmp/go-build189039928/b001/_testmain.go:44:42: assign, m := (*testing.M)(~R0) at $WORK/b001/_testmain.go:44:4 /tmp/go-build189039928/b001/_testmain.go:44:42: flow: heap = m: /tmp/go-build189039928/b001/_testmain.go:44:42: call parameter, m.Run() at $WORK/b001/_testmain.go:46:15 /tmp/go-build189039928/b001/_testmain.go:44:42: testdeps.TestDeps literal escapes to heap /tmp/go-build189039928/b001/_testmain.go:44:24: &testing.M literal escapes to heap goos: linux goarch: amd64 pkg: github.com/ardanlabs/gotraining/topics/go/profiling/memcpu BenchmarkAlgorithmOne-36 1595413 2258 ns/op BenchmarkAlgorithmTwo-36 7543050 451 ns/op PASS ok github.com/ardanlabs/gotraining/topics/go/profiling/memcpu 9.816s ```

[ardan-bkennedy]

Looking for everything about stream.go:83

Listing 1 : Actionable

./stream.go:83:26: inlining call to bytes.NewBuffer func([]byte) *bytes.Buffer { return &bytes.Buffer literal }

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

./stream.go:83:26: &bytes.Buffer literal escapes to heap:

Listing 2 is good. I have found the beginning of the report for line 83 having an allocation.

Listing 3 : NOT Actionable

./stream.go:83:26:  flow: ~R0 = &(temp for &bytes.Buffer literal):
./stream.go:83:26:    spill, &bytes.Buffer literal at ./stream.go:83:26
./stream.go:83:26:    assign-pair, ~R0 = &bytes.Buffer literal at ./stream.go:83:26

Maybe it's eluding to the fact that when the inlining took place, the bytes.Buffer value was constructed here using pointer semantics. input := &bytes.Buffer{}. Maybe R0 represents the input variable?

Listing 4 : NOT Actionable

./stream.go:83:26:  flow: input = ~R0:
./stream.go:83:26:    assign, input := (*bytes.Buffer)(~R0) at ./stream.go:83:8

Maybe it's validating that R0 is a pointer of type bytes.Buffer which is ending up being assigned to the input variable.

Listing 5 : Actionable

./stream.go:83:26:  flow: io.r = input:
./stream.go:83:26:    interface-converted, input at ./stream.go:113:28
./stream.go:83:26:    assign-pair, io.r, io.buf = input, buf[:end] at ./stream.go:113:28

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

./stream.go:83:26: &bytes.Buffer literal escapes to heap
./stream.go:83:26:  from ~R0 (assign-pair) at ./stream.go:83:26
./stream.go:83:26:  from input (assigned) at ./stream.go:83:8
./stream.go:83:26:  from input (interface-converted) at ./stream.go:93:26
./stream.go:83:26:  from io.r (assign-pair) at ./stream.go:93:26
./stream.go:83:26:  from io.r (passed to call[argument escapes]) at ./stream.go:93:26

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. Line 93 and 113 look like this. if n, err := io.ReadFull(input, buf[:end]); err != nil {

Listing 6 : Actionable

./stream.go:83:26:  flow: heap = io.r:
./stream.go:83:26:    call parameter, io.ReadAtLeast(io.r, io.buf, len(io.buf)) at ./stream.go:113:28

This is giving me the extra information that it the passing of input as a parameter to the Read call that is causing the problem.

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.

./stream.go:89:13: make([]byte, size) escapes to heap:
./stream.go:89:13:  flow: heap = &(temp for make([]byte, size)):
./stream.go:89:13:    must heap alloc, make([]byte, size) at ./stream.go:89:13

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 non-constant size. This new report is providing no indication as to why.

Conclusion

Losing this information hurts and should be provided. A better message like, unknow size or something more clear about that should be provided.

[cherrymui]

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.

[mdempsky]

Thanks @ardan-bkennedy! I think that was helpful.

Maybe it's eluding to the fact that when the inlining took place, the bytes.Buffer value was constructed here using pointer semantics. input := &bytes.Buffer{}. Maybe R0 represents the input variable?

~R0 here is the temporary variable introduced during inlining to represent the result parameter. For example, given:

package p
func Foo(x int) *T { return &T{x} }

then:

input := p.Foo(42)

gets processed by inlining into:

p.x := 42
~R0 := &p.T{p.x}
input := ~R0

Maybe it's validating that R0 is a pointer of type bytes.Buffer which is ending up being assigned to the input variable.

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).

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.

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.

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.

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.)

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 non-constant size. This new report is providing no indication as to why.

Thanks, I'll restore the original, clearer wording. ("must heap alloc" was just placeholder text anyway.)

[ardan-bkennedy]

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.

[mdempsky]

@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:

1. I'm thinking of reporting inlining position information, which may make things easier to understand (or might just make it noisier).
2. Currently, the notes (e.g., "assign-pair", "interface-converted") are pretty ad hoc, and I think there are some blind spots. I want to clean this up and make it more principled.

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:

package p

var sink interface{}

func foo() {
        p := new(int)    // line 6
        sink = &p        // line 7
}

We used to report this as:

/tmp/u.go:7:14: &p escapes to heap
/tmp/u.go:7:14:     from sink (assigned to top level variable) at /tmp/u.go:7:14
/tmp/u.go:6:2: moved to heap: p
/tmp/u.go:6:10: new(int) escapes to heap
/tmp/u.go:6:10:     from p (assigned) at /tmp/u.go:6:4
/tmp/u.go:6:10:     from &p (address-of) at /tmp/u.go:7:16
/tmp/u.go:6:10:     from &p (interface-converted) at /tmp/u.go:7:14
/tmp/u.go:6:10:     from sink (assigned to top level variable) at /tmp/u.go:7:14

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 p is heap allocated?

For example, what if it instead reported something like:

/tmp/u.go:7:14: &p escapes to heap
/tmp/u.go:7:14:     from sink (assigned to top level variable) at /tmp/u.go:7:14
/tmp/u.go:6:2: moved to heap: p
/tmp/u.go:6:10: new(int) escapes to heap
/tmp/u.go:6:10:     from p (assigned) at /tmp/u.go:6:4
/tmp/u.go:6:10:     [p allocated on heap; reported above]

[ardan-bkennedy]

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.

/tmp/u.go:6:10: p escapes to heap
/tmp/u.go:6:10:      (interface-assignment) at /tmp/u.go:7:14

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.

[mdempsky]

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.

To be clear, there are two separate allocations here: the p variable declaration and the new(int) expression.

1. p is heap allocated because its address is assigned to the package-scope variable sink, that's why the old message was "assigned to top level variable".

   (sink being interface-typed is a red herring here. &p is pointer-typed, so it can be stored into the interface{}'s data pointer field without indirection. In particular, sink = &p would still require p to be heap allocated even if sink was declared as var sink **int.)

2. new(int) is heap allocated because the resulting address is stored in p, which in turn is heap allocated (see above).

It's this latter allocation that I'm asking about here. In particular, when explaining why new(int) is heap allocated, we used to include a redundant explanation that p escapes:

/tmp/u.go:6:10:     from &p (address-of) at /tmp/u.go:7:16
/tmp/u.go:6:10:     from &p (interface-converted) at /tmp/u.go:7:14
/tmp/u.go:6:10:     from sink (assigned to top level variable) at /tmp/u.go:7:14

Are these three lines useful to understanding why new(int) escaped?

[ardan-bkennedy]

Ohh, I missed the double indirection! Without the double indirection there is only one allocation which is the p variable thanks to the interface assignment.

Given this benchmark

package main

import "testing"

var sink interface{}

func BenchmarkBill(b *testing.B) {
    for i := 0; i < b.N; i++ {
        p := new(int)
        sink = &p
    }
}

Running the benchmark with this command

$ go test -bench . -benchtime 3s -benchmem  -memprofile p.out
goos: darwin
goarch: amd64
pkg: github.com/ardanlabs/gotraining/topics
BenchmarkBill-12        140658207           25.1 ns/op        16 B/op          2 allocs/op
PASS
ok      github.com/ardanlabs/gotraining/topics  6.196s

Looking at the profile, which is interesting because both allocations are being reported on line 9.

$ go tool pprof p.out
Type: alloc_space
Time: Sep 25, 2019 at 9:22pm (EDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list main
Total: 3.56GB
(pprof) list Bill
Total: 3.56GB
ROUTINE ======================== github.com/ardanlabs/gotraining/topics.BenchmarkBill in /Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/main_test.go
    3.56GB     3.56GB (flat, cum)   100% of Total
         .          .      4:
         .          .      5:var sink interface{}
         .          .      6:
         .          .      7:func BenchmarkBill(b *testing.B) {
         .          .      8:   for i := 0; i < b.N; i++ {
    3.56GB     3.56GB      9:       p := new(int)
         .          .     10:       sink = &p
         .          .     11:   }
         .          .     12:}
(pprof)

I would say the following:

LIne 09 is constructing a value of type int set to it's zero value and storing the address of this new integer in pointer variable p. This alone does not consistute an allocation of the new integer value or the p variable.

Line 10 is assigning the address of p inside the interface. Storing the address of p represents double indirection to the integer value. Now there are two allocations. The p variable allocates because once it is stored inside the interface, it requires an allocation. Since p is pointing to an integer, that integer now has to allocation. We end up with two allocations worth 16 bytes.

Back to the code.

var sink interface{}

func foo() {
        p := new(int)    // line 6
        sink = &p        // line 7
}

I was super confused with the word sink in your report. For some reason I didn't equate that to a variable in the code. I thought you were using some internal technical term. It might have been because the sink variable wasn't allocating so why would it be presented on this line.

Now understanding the code and allocations better. Maybe this is better knowing line 6 will be reported by the profiler.

/tmp/u.go:6:10: p escapes to heap
/tmp/u.go:6:10:     from sink (interface-converted) at /tmp/u.go:7:14
/tmp/u.go:6:10: new(int) escapes to heap
/tmp/u.go:6:10:     from &p (assigned-double-indirection) at /tmp/u.go:7:14

This is very very hard. I have been thinking about this for 20 minutes. I have no good answers. :(

[mdempsky]

Thanks for the feedback, @ardan-bkennedy. That was really helpful.

I think my two key takeaways at the moment are:

1. You want the line numbers on the left-hand side to match the line numbers where go tool pprof reports heap allocations. That's definitely doable. (And somewhere I think escape.go can do better than esc.go did.)

2. It seems like you prefer shorter explanations rather than long redundant ones. That's good, because the compiler doesn't like doing redundant work. :)

This is very very hard. I have been thinking about this for 20 minutes. I have no good answers. :(

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.

[ardan-bkennedy]

Hi @mdempsky, I was playing on gotip today and didn't see anything new from this issue. Curious if you have any updates?

[mdempsky]

@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.

[mdempsky]

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.

[ardan-bkennedy]

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.

[gopherbot]

Change https://golang.org/cl/205917 mentions this issue: cmd/compile: restore more missing -m=2 escape analysis details

[mdempsky]

@ardan-bkennedy

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.

Thanks, this should be fixed now.

[ardan-bkennedy]

Brilliantly Done!

./stream.go:89:13: make([]byte, size) escapes to heap:
./stream.go:89:13:   flow: {heap} = &{storage for make([]byte, size)}:
./stream.go:89:13:     from make([]byte, size) (non-constant size) at ./stream.go:89:13

[ardan-bkennedy]

Kick-Ass job @mdempsky !! Thanks for all the effort on this. Very much appreciated!