Skip to content
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

Jump to bottom

runtime/pprof: memory profile attributes allocation to import line #23049

Closed
sjlee opened this issue Dec 8, 2017 · 7 comments
Closed

runtime/pprof: memory profile attributes allocation to import line #23049

sjlee opened this issue Dec 8, 2017 · 7 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone
Unplanned

Comments

@sjlee
Copy link

sjlee commented Dec 8, 2017

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
Copy link
Author

sjlee commented Dec 8, 2017

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

@titanous titanous changed the title memory profile attributes allocation to import line runtime/pprof: memory profile attributes allocation to import line Dec 8, 2017
@titanous
Copy link
Member

titanous commented Dec 8, 2017

Does this also happen when using go1.10beta1?

@titanous titanous added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Dec 8, 2017
@sjlee
Copy link
Author

sjlee commented Dec 18, 2017

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
Copy link
Contributor

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

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

@ianlancetaylor ianlancetaylor added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 29, 2018
@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Mar 29, 2018
@sjlee
Copy link
Author

sjlee commented Mar 29, 2018

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
Copy link
Contributor

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

@sjlee
Copy link
Author

sjlee commented Mar 29, 2018

SGTM.

@golang golang locked and limited conversation to collaborators Mar 29, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
Unplanned
Development

No branches or pull requests
4 participants
@titanous @sjlee @ianlancetaylor @gopherbot