runtime/pprof: memory profile attributes allocation to import line

[sjlee]

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go version go1.9.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"

The profile itself was captured on a Linux docker container, and was viewed on MacOS (both on 1.9.2).

What did you do?

I opened a memory profile in the --alloc_objects mode. I listed a function to view its allocation, and it associated the allocation that was meant for bytes.NewBuffer with an import line in the source that imported the bytes package. Output from list:

(pprof) list encodeNameValuePairs
Total: 534804146
ROUTINE ======================== ...protocol.(*Msg).encodeNameValuePairs in .../message.go
  24057960   27540717 (flat, cum)  5.15% of Total
         .          .      1:package protocol
         .          .      2:
         .          .      3:import (
  12092676   12092676      4:	"bytes"
         .          .      5:	"fmt"

(lines that do not belong to the function omitted)

         .          .    148:func (m *Msg) encodeNameValuePairs(val map[string]string) []byte {
  11965284   11965284    149:	buf := bytes.NewBuffer(make([]byte, 0, defaultNVPairSize))
         .          .    150:	for k, v := range val {
         .          .    151:		if buf.Len() > 0 {
         .      36437    152:			buf.WriteByte('&')
         .          .    153:		}
         .     412648    154:		writeEscaped(k, buf)
         .      37803    155:		buf.WriteByte('=')
         .    2995869    156:		writeEscaped(v, buf)
         .          .    157:	}
         .          .    158:	return buf.Bytes()
         .          .    159:}
         .          .    160:

I confirmed that the first allocation number (12092676) is indeed caused by bytes.NewBuffer by writing a small program to match the allocation numbers from this function.

What did you expect to see?

The first allocation number (12092676) to be correctly attributed to the actual line.

What did you see instead?

It was attributed to the import line.

[sjlee]

If I view the same memory profile with --alloc_space, I see the same incorrect behavior.

[titanous]

Does this also happen when using go1.10beta1?

[sjlee]

I will try it when I get a chance. Just to be sure, did you mean generating the profile with 1.10 beta or viewing the profile with 1.10 beta?

[ianlancetaylor]

Can you give us instructions for how to reproduce the problem ourselves?

To answer your question: generating the profile with (now) 1.10.1.

[sjlee]

I got around to reproducing this issue with 1.9.x. I can also confirm that this is fixed in 1.10. Here is some sample code that can show you the bug:

package main

import (
	"bytes"
	"fmt"
	"testing"
)

func BenchmarkTestWriteNameValuePairs(b *testing.B) {
	m := make(map[string]string)
	m["foo"] = "bar"
	m["bad"] = "good"
	for i := 0; i < b.N; i++ {
		b := writeNameValuePairs(m)
		fmt.Printf("%d bytes written\n", len(b))
	}
}

func writeNameValuePairs(val map[string]string) []byte {
	buf := bytes.NewBuffer(make([]byte, 0, 512))
	for k, v := range val {
		if buf.Len() > 0 {
			buf.WriteByte('&')
		}
		buf.WriteString(k)
		buf.WriteByte('=')
		buf.WriteString(v)
	}
	return buf.Bytes()
}

When you run it with go 1.9.x, do go tool pprof --alloc_objects ..., and list writeNameValuePairs, you'll see (I scrubbed the paths)

(pprof) list writeNameValuePairs
Total: 1421345
ROUTINE ======================== .../pprof.writeNameValuePairs in /.../pprof/newbuffer_test.go
    524344     524344 (flat, cum) 36.89% of Total
         .          .      1:package main
         .          .      2:
         .          .      3:import (
    524344     524344      4:	"bytes"
         .          .      5:	"fmt"
         .          .      6:	"testing"
ROUTINE ======================== .../pprof.writeNameValuePairs in /.../pprof/newbuffer_test.go
    500980     500980 (flat, cum) 35.25% of Total
         .          .     15:		fmt.Printf("%d bytes written\n", len(b))
         .          .     16:	}
         .          .     17:}
         .          .     18:
         .          .     19:func writeNameValuePairs(val map[string]string) []byte {
    500980     500980     20:	buf := bytes.NewBuffer(make([]byte, 0, 512))
         .          .     21:	for k, v := range val {
         .          .     22:		if buf.Len() > 0 {
         .          .     23:			buf.WriteByte('&')
         .          .     24:		}
         .          .     25:		buf.WriteString(k)

With 1.10, you'll see

(pprof) list writeNameValuePairs
Total: 689862
ROUTINE ======================== .../pprof.writeNameValuePairs in /.../pprof/newbuffer_test.go
    193630     460483 (flat, cum) 66.75% of Total
         .          .     15:		fmt.Printf("%d bytes written\n", len(b))
         .          .     16:	}
         .          .     17:}
         .          .     18:
         .          .     19:func writeNameValuePairs(val map[string]string) []byte {
    193630     460483     20:	buf := bytes.NewBuffer(make([]byte, 0, 512))
         .          .     21:	for k, v := range val {
         .          .     22:		if buf.Len() > 0 {
         .          .     23:			buf.WriteByte('&')
         .          .     24:		}
         .          .     25:		buf.WriteString(k)

[ianlancetaylor]

Thanks. If it's fixed in 1.10, we're happy. We aren't going to backport the fix to 1.9.

[sjlee]

SGTM.