Help using pprof

[Brendan Tracey]

Still using 1.0.3, and trying to use pprof, but I do not understand it.

My code starts like 

http://play.golang.org/p/JTHRjww43b

and I modify it to be

http://play.golang.org/p/33xdWg36gq , as described in http://golang.org/pkg/net/http/pprof/ .

When I run the command described in pprof, I get an error.

brendan:~/Documents/mygo/src$ go tool pprof http://localhost:6060/debug/pprof/heap

Read http://localhost:6060/debug/pprof/symbol

Use of uninitialized value $line in substitution (s///) at /usr/local/go/pkg/tool/darwin_amd64/pprof line 2957.

http://localhost:6060/debug/pprof/symbol doesn't exist

go tool pprof: exit status 1

This isn't surprising, but I do not understand what I should do differently. The "profiling go programs" talks about goprof which seems not to exist, and neither does go prof. I can run go test -cpuprofile cpu.out ransuq/neuralnetcalller.go , but I'm not sure how to interpret the result.

Thanks

[Volker Dobler]

Not sure if profiling works on Mac.  See e.g.

https://groups.google.com/d/msg/golang-nuts/_5Fu5eQwwXA/Rk5yqnHC2dwJ

V.

[Rob Pike]

I regularly profile on a Mac.

-rob

[Volker Dobler]

Completely untested. The tool is pprof with two p.

Try something along

$ cd <pathtoyourpackage>

$ go test -c

$ ./<ourpackagename>.test -test.cpuprofile cpu.out

$ go tool pprof <yourpackagename>.test

V.

Am Mittwoch, 10. April 2013 00:09:16 UTC+2 schrieb Brendan Tracey:

[Dave Cheney]

On 10/04/2013, at 9:11, Volker Dobler <dr.volke...@gmail.com> wrote:

Completely untested. The tool is pprof with two p.

Try something along

$ cd <pathtoyourpackage>

$ go test -c

$ ./<ourpackagename>.test -test.cpuprofile cpu.out

$ go tool pprof <yourpackagename>.test

You need to pass the binary and cpu.out to pprof, otherwise you get a cryptic error. 

V.

Am Mittwoch, 10. April 2013 00:09:16 UTC+2 schrieb Brendan Tracey:

Still using 1.0.3, and trying to use pprof, but I do not understand it.

My code starts like 

http://play.golang.org/p/JTHRjww43b

and I modify it to be

http://play.golang.org/p/33xdWg36gq , as described in http://golang.org/pkg/net/http/pprof/ .

When I run the command described in pprof, I get an error.

brendan:~/Documents/mygo/src$ go tool pprof http://localhost:6060/debug/pprof/heap

Read http://localhost:6060/debug/pprof/symbol

Use of uninitialized value $line in substitution (s///) at /usr/local/go/pkg/tool/darwin_amd64/pprof line 2957.

http://localhost:6060/debug/pprof/symbol doesn't exist

go tool pprof: exit status 1

This isn't surprising, but I do not understand what I should do differently. The "profiling go programs" talks about goprof which seems not to exist, and neither does go prof. I can run go test -cpuprofile cpu.out ransuq/neuralnetcalller.go , but I'm not sure how to interpret the result.

Thanks

--
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.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Brendan Tracey]

Could you give a code example?

[Dave Cheney]

lucky(~/go/src/pkg/bytes) % go test -c
lucky(~/go/src/pkg/bytes) % ./bytes.test -test.run=XXX
-test.bench=Index -test.cpuprofile=cpu.out
PASS
BenchmarkIndexByte32 200000000 8.23 ns/op 3887.42 MB/s
BenchmarkIndexByte4K 10000000 264 ns/op 15473.34 MB/s
BenchmarkIndexByte4M 10000 249057 ns/op 16840.68 MB/s
BenchmarkIndexByte64M 500 3989244 ns/op 16822.45 MB/s
BenchmarkIndexBytePortable32 50000000 45.6 ns/op
702.25 MB/s
BenchmarkIndexBytePortable4K 1000000 2618 ns/op
1564.52 MB/s
BenchmarkIndexBytePortable4M 1000 2659567 ns/op
1577.06 MB/s
BenchmarkIndexBytePortable64M 50 42553580 ns/op
1577.04 MB/s
BenchmarkIndex32 10000000 222 ns/op 143.77 MB/s
BenchmarkIndex4K 50000 38103 ns/op 107.50 MB/s
BenchmarkIndex4M 50 38845263 ns/op 107.97 MB/s
BenchmarkIndex64M 5 622904900 ns/op 107.74 MB/s
BenchmarkIndexEasy32 50000000 45.6 ns/op 702.37 MB/s
BenchmarkIndexEasy4K 5000000 304 ns/op 13437.60 MB/s
BenchmarkIndexEasy4M 10000 250816 ns/op 16722.61 MB/s
BenchmarkIndexEasy64M 500 3980612 ns/op 16858.93 MB/s
lucky(~/go/src/pkg/bytes) % go tool pprof bytes.test cpu.out
Welcome to pprof! For help, type 'help'.
(pprof) top10
Total: 3992 samples
1686 42.2% 42.2% 1686 42.2% bytes.IndexByte
978 24.5% 66.7% 978 24.5% bytes.indexBytePortable
626 15.7% 82.4% 1920 48.1% bytes.Index
379 9.5% 91.9% 379 9.5% runtime.memeqbody
151 3.8% 95.7% 530 13.3% bytes.Equal
138 3.5% 99.1% 2038 51.1% bytes_test.bmIndexByte
22 0.6% 99.7% 904 22.6% bytes_test.bmIndexEasy
11 0.3% 100.0% 1045 26.2% bytes_test.bmIndex
1 0.0% 100.0% 1 0.0% scanblock
0 0.0% 100.0% 244 6.1% bytes_test.BenchmarkIndex32
(pprof)

[Brendan Tracey]

Okay, got it, thanks. 

Is profiling supposed to be accurate on OSX? When I run your code, I get

brendan:/usr/local/go/src/pkg/bytes$ ./bytes.test -test.run=XXX -test.bench=Index -test.cpuprofile=cpu.out

PASS

BenchmarkIndexByte32 500000000         6.41 ns/op 4991.16 MB/s

BenchmarkIndexByte4K 10000000       234 ns/op 17485.55 MB/s

BenchmarkIndexByte4M   10000    232787 ns/op 18017.77 MB/s

BenchmarkIndexByte64M     500   4454674 ns/op 15064.82 MB/s

BenchmarkIndexBytePortable32 50000000        55.2 ns/op 579.43 MB/s

BenchmarkIndexBytePortable4K  500000      4667 ns/op 877.54 MB/s

BenchmarkIndexBytePortable4M     500   4708306 ns/op 890.83 MB/s

BenchmarkIndexBytePortable64M      20  75758500 ns/op 885.83 MB/s

BenchmarkIndex32 5000000       672 ns/op  47.59 MB/s

BenchmarkIndex4K   10000    104045 ns/op  39.37 MB/s

BenchmarkIndex4M      20 106558750 ns/op  39.36 MB/s

BenchmarkIndex64M       1 1706678000 ns/op  39.32 MB/s

BenchmarkIndexEasy32 50000000        57.3 ns/op 557.99 MB/s

BenchmarkIndexEasy4K 10000000       285 ns/op 14365.22 MB/s

BenchmarkIndexEasy4M   10000    231526 ns/op 18115.87 MB/s

BenchmarkIndexEasy64M     500   4425492 ns/op 15164.16 MB/s

brendan:/usr/local/go/src/pkg/bytes$ go tool pprof bytes.test cpu.out

Welcome to pprof!  For help, type 'help'.

(pprof) top10

Total: 3124 samples

    3124 100.0% 100.0%     3124 100.0% strconv.quoteWith

       0   0.0% 100.0%        7   0.2% time.Now

(pprof) quit

and on my own code it is telling me that a function is taking 46% of the run time, when that function is less than 1% of the run time. 

[Brendan Tracey]

Sorry, I'm using 10.8.3

[Volker Dobler]

Not sure about Mac, sorry.

I think profile information is gathered periodically

and might miss calls. Either make sure your tests

run long enough (use -test.benchtime) or you might

increase 

http://golang.org/pkg/runtime/#SetCPUProfileRate

V.

[Brendan Tracey]

The code takes two minutes to run, so I'm guessing that's not the issue. Thanks for the suggestion though.

Also, I didn't specify before, but my code is being profiled like in "profiling go programs", not with go test.

[minux]

On Wed, Apr 10, 2013 at 2:18 PM, Brendan Tracey
<tracey....@gmail.com> wrote:
> Okay, got it, thanks.
>
> Is profiling supposed to be accurate on OSX? When I run your code, I get

There are some problems profiling on Mac OS X 10.6.x with the 64-bit kernel.
But I think the problem is fixed in latter versions.
> brendan:/usr/local/go/src/pkg/bytes$ go tool pprof bytes.test cpu.out

> Welcome to pprof! For help, type 'help'.
> (pprof) top10

> Total: 3124 samples
> 3124 100.0% 100.0% 3124 100.0% strconv.quoteWith
> 0 0.0% 100.0% 7 0.2% time.Now
>

[Dave Cheney]

Maybe not, Brendan is on 10.8.3.

[Brendan Tracey]

Is there anything I can do to help figure out the problem, or is this a problem with pprof and not go?

[andrey mirtchovski]

just a shot in the dark, but did you do what all.bash suggests in the end:

"On OS X the debuggers must be installed setgid procmod.
Read and run ./sudo.bash to install the debuggers."

i'm on 10.8.3 and am not experiencing your issues:

$ go tool pprof http://localhost:6060/debug/pprof/heap
Read http://localhost:6060/debug/pprof/symbol

Fetching /pprof/heap profile from localhost:6060 to
/Users/aam/pprof/mcclamd.1365605759.localhost-port6060.pprof.heap
Wrote profile to
/Users/aam/pprof/mcclamd.1365605759.localhost-port6060.pprof.heap
Adjusting heap profiles for 1-in-524288 sampling rate

Welcome to pprof! For help, type 'help'.
(pprof) top10

Total: 1.5 MB
1.0 66.7% 66.7% 1.0 66.7% runtime/pprof.writeGoroutineStacks
0.5 33.3% 100.0% 0.5 33.3% main.reader
0.0 0.0% 100.0% 1.5 100.0% gosched0
0.0 0.0% 100.0% 0.5 33.3% main.main
0.0 0.0% 100.0% 1.0 66.7% net/http.(*ServeMux).ServeHTTP
0.0 0.0% 100.0% 1.0 66.7% net/http.(*conn).serve
0.0 0.0% 100.0% 1.0 66.7% net/http.HandlerFunc.ServeHTTP
0.0 0.0% 100.0% 1.0 66.7% net/http.serverHandler.ServeHTTP
0.0 0.0% 100.0% 1.0 66.7% net/http/pprof.Index
0.0 0.0% 100.0% 1.0 66.7% net/http/pprof.handler.ServeHTTP
(pprof)

[Brendan Tracey]

Thanks for the suggestion, but I tried running it and it said it doesn't need to be run. I'll try upgrading to tip and see if that changes anything.

[minux]

On Wed, Apr 10, 2013 at 10:59 PM, andrey mirtchovski
<mirtc...@gmail.com> wrote:
> just a shot in the dark, but did you do what all.bash suggests in the end:
>
> "On OS X the debuggers must be installed setgid procmod.
> Read and run ./sudo.bash to install the debuggers."

it is for cmd/cov and cmd/prof (note: not pprof), so you don't need to run
sudo.bash to use pprof (double p here).

[andrey mirtchovski]

> brendan:~/Documents/mygo/src$ go tool pprof
> http://localhost:6060/debug/pprof/heap
> Read http://localhost:6060/debug/pprof/symbol
> Use of uninitialized value $line in substitution (s///) at
> /usr/local/go/pkg/tool/darwin_amd64/pprof line 2957.
> http://localhost:6060/debug/pprof/symbol doesn't exist
> go tool pprof: exit status 1

I was finally able to emulate this error by shutting down the listener on port 6060:

$ curl http://localhost:6060/debug/pprof/heap
curl: (7) Failed connect to localhost:6060; Connection refused

$ go tool pprof http://localhost:6060/debug/pprof/heap
Read http://localhost:6060/debug/pprof/symbol

Use of uninitialized value $line in substitution (s///) at /Users/andrey/go/pkg/tool/darwin_amd64/pprof line 2970.

http://localhost:6060/debug/pprof/symbol doesn't exist

$ godoc -http=:6060 &

$ go tool pprof http://localhost:6060/debug/pprof/heap
Read http://localhost:6060/debug/pprof/symbol

[...]
$ curl http://localhost:6060/debug/pprof/heap
heap profile: 2: 17760 [62: 1605008] @ heap/1048576
1: 17664 [1: 17664] @ 0x4cb6a 0x35378 0x36a37 0x37ce7 0x37d6d 0x60465 0x282a5 0x44148 0x46120
[...]