heap profiling does not work on M2 MacBook air?

[Jochen Voss]

Dear all,

I'm trying to profile memory use of a program, following the instructions at https://go.dev/blog/pprof , but I can't get memory profiling to work.  Am I doing things wrong, or is this broken?

Simplified code is at https://go.dev/play/p/Wq_OU49LVQZ .  (The code doesn't run on the playground, but you can download it and run it locally.)

Following the advice from https://pkg.go.dev/runtime/pprof I added the following code to the end of my main() function:

f, err := os.Create("mem.prof")

if err != nil {

log.Fatal("could not create memory profile: ", err)

}

runtime.GC() // get up-to-date statistics

if err := pprof.WriteHeapProfile(f); err != nil {

log.Fatal("could not write memory profile: ", err)

}

err = f.Close()

if err != nil {

log.Fatal(err)

}

When I run the code, this gives me a "mem.prof" file (5084 bytes).  But when I start "go tool pprof" on this file, I get

>>> go tool pprof xxx mem.prof
File: xxx
Type: inuse_space
Time: Mar 1, 2023 at 1:15pm (GMT)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%

There seem to be no samples in this file.

What am I doing wrong?

All the best,

Jochen

[Jochen Voss]

The problem also occurs on AMD64 Linux, so it's not architecture specific.  Hints would be most welcome!

[Sean Liao]

fwiw, that code works on my machine :tm:

1:40:47 ~/tmp/testrepo0120 0:00:27
main » go run .              
1:40:58 ~/tmp/testrepo0120 0:00:08
main » go tool pprof mem.prof
File: testrepo0120
Type: inuse_space
Time: Mar 2, 2023 at 1:40am (CST)

Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10

Showing nodes accounting for 513.31kB, 100% of 513.31kB total

      flat  flat%   sum%        cum   cum%

  513.31kB   100%   100%   513.31kB   100%  regexp/syntax.(*compiler).inst (inline)
         0     0%   100%   513.31kB   100%  regexp.Compile (inline)
         0     0%   100%   513.31kB   100%  regexp.MustCompile
         0     0%   100%   513.31kB   100%  regexp.compile
         0     0%   100%   513.31kB   100%  regexp/syntax.(*compiler).compile
         0     0%   100%   513.31kB   100%  regexp/syntax.(*compiler).rune
         0     0%   100%   513.31kB   100%  regexp/syntax.Compile
         0     0%   100%   513.31kB   100%  runtime.doInit
         0     0%   100%   513.31kB   100%  runtime.main
         0     0%   100%   513.31kB   100%  seehuhn.de/go/pdf/font/tounicode.init

- sean

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/4e85c396-ef29-41d5-9bb6-5b950648287fn%40googlegroups.com.

[Jochen Voss]

Dear Sean,

Thanks for trying this out.  Your result is different from mine, but I don't think this can be right.  According to the output, the only allocation would be inside the regexp module.  But there should be many more allocations (for example in line 56 of the code)!

All the best,

Jochen

[Miguel Angel Rivera Notararigo]

Try commenting runtime.GC

To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/32579fb7-773f-49e3-bfe1-a9af4a292dd9n%40googlegroups.com.

[peterGo]

Jochen Voss,

On linux/amd64

xxx.go: https://go.dev/play/p/Wq_OU49LVQZ

$ go build xxx.go && ./xxx

$ go tool pprof xxx mem.prof
File: xxx
Type: inuse_space
Time: Mar 1, 2023 at 11:03pm (EST)

No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)

(pprof) quit

$ go tool pprof -alloc_space xxx mem.prof
File: xxx
Type: alloc_space
Time: Mar 1, 2023 at 11:03pm (EST)

Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top

Showing nodes accounting for 6919.54MB, 98.93% of 6994.32MB total
Dropped 77 nodes (cum <= 34.97MB)
Showing top 10 nodes out of 18

      flat  flat%   sum%        cum   cum%

 3564.91MB 50.97% 50.97%  3564.91MB 50.97%  golang.org/x/exp/slices.Insert[...] (inline)
 3073.64MB 43.94% 94.91%  3073.64MB 43.94%  seehuhn.de/go/layout.(*Skip).Minus
  123.51MB  1.77% 96.68%   123.51MB  1.77%  seehuhn.de/go/layout.(*Skip).Clone (inline)
  104.50MB  1.49% 98.17%  6866.56MB 98.17%  seehuhn.de/go/layout.(*knuthPlassLineBreaker).Run
   48.48MB  0.69% 98.87%    60.68MB  0.87%  compress/flate.NewWriter
    4.50MB 0.064% 98.93%  6878.06MB 98.34%  seehuhn.de/go/layout.(*Engine).EndParagraph
         0     0% 98.93%    60.68MB  0.87%  compress/flate.NewWriterDict
         0     0% 98.93%    60.68MB  0.87%  compress/zlib.(*Writer).Write
         0     0% 98.93%    60.68MB  0.87%  compress/zlib.(*Writer).writeHeader
         0     0% 98.93%    56.12MB   0.8%  fmt.Fprintln
(pprof) quit
$

Peter

[Jochen Voss]

Hi Peter,

Thanks a lot, giving the "-alloc_space" option makes all the difference!  With this option, it also works for me.

I wonder whether it meant to be the way that you have to give this option.  Maybe something broke?  In the blog entry https://go.dev/blog/pprof they didn't need this option to get the profile output.

All the best,

Jochen

[peterGo]

On Thursday, March 2, 2023 at 2:03:22 AM UTC-5 Jochen Voss wrote:

Hi Peter,

Thanks a lot, giving the "-alloc_space" option makes all the difference!  With this option, it also works for me.

I wonder whether it meant to be the way that you have to give this option.  Maybe something broke?  In the blog entry https://go.dev/blog/pprof they didn't need this option to get the profile output.

The Go blog post at https://go.dev/blog/pprof was written in 2011; it is now 2023. For up-to-date information, see the latest pprof package documentation at https://pkg.go.dev/runtime/pprof@latest.

The pprof package documentation is incorrect:

To add equivalent [go test] profiling support to a standalone program, add code like the following to your main function:

    // ...

    runtime.GC() // get up-to-date statistics

    if err := pprof.WriteHeapProfile(f); err != nil {
        log.Fatal("could not write memory profile: ", err)
    }

    // ...

To obtain equivalent results, replace the above code with:

    // ...

    runtime.GC() // get up-to-date statistics

    if allocs := pprof.Lookup("allocs"); allocs == nil {
        log.Fatal("could not lookup memory profile: ")
    } else if err := allocs.WriteTo(f, 0); err != nil {

        log.Fatal("could not write memory profile: ", err)
    }

    // ...

For your example,

yyy.go: https://go.dev/play/p/epy4c3et1Io

$ go build yyy.go && ./yyy
$ go tool pprof mem.prof
File: yyy
Type: alloc_space
Time: Mar 2, 2023 at 10:02am (EST)

Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top

Showing nodes accounting for 6975.42MB, 98.93% of 7050.77MB total
Dropped 62 nodes (cum <= 35.25MB)

Showing top 10 nodes out of 18
      flat  flat%   sum%        cum   cum%

 3564.88MB 50.56% 50.56%  3564.88MB 50.56%  golang.org/x/exp/slices.Insert[...] (inline)
 3122.14MB 44.28% 94.84%  3122.14MB 44.28%  seehuhn.de/go/layout.(*Skip).Minus
  117.01MB  1.66% 96.50%   117.01MB  1.66%  seehuhn.de/go/layout.(*Skip).Clone (inline)
  115.51MB  1.64% 98.14%  6919.54MB 98.14%  seehuhn.de/go/layout.(*knuthPlassLineBreaker).Run
   52.89MB  0.75% 98.89%    65.63MB  0.93%  compress/flate.NewWriter
    2.50MB 0.035% 98.92%  6926.54MB 98.24%  seehuhn.de/go/layout.(*Engine).EndParagraph
    0.50MB 0.0071% 98.93%  7050.27MB   100%  main.main
         0     0% 98.93%    65.63MB  0.93%  compress/flate.NewWriterDict
         0     0% 98.93%    65.63MB  0.93%  compress/zlib.(*Writer).Write
         0     0% 98.93%    65.63MB  0.93%  compress/zlib.(*Writer).writeHeader
(pprof) quit
$

Peter

[Jochen Voss]

Hi Peter,

Thanks again for looking into this, and for your help!

You mention that the blog post was long ago.  I wonder whether the code to write profile information is covered by the compatibility promise.  If so, probably the legacy WriteHeapProfile function could be made to implement the required code to keep this working.  Should a bug report be filed to this effect? 

Similarly, should a bug report be filed about the mistake you found in the pprof package documentation?

All the best,

Jochen

[Jochen Voss]

I've now filed https://github.com/golang/go/issues/65328 to report this.