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

cmd/pprof: heap command top and traces show different data #34236

Closed
q2683252 opened this issue Sep 11, 2019 · 3 comments
Closed

cmd/pprof: heap command top and traces show different data #34236

q2683252 opened this issue Sep 11, 2019 · 3 comments

Comments

@q2683252
Copy link

@q2683252 q2683252 commented Sep 11, 2019

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

$ go version
go version go1.11.5 linux/amd64

Does this issue reproduce with the latest release?

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

$ go env GOARCH="amd64" GOBIN="" GOCACHE="/data/tbase/.cache/go-build" GOEXE="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOOS="linux" GOPATH="/data/tbase/oss_compile/golang_pkg/packages:" GOPROXY="" GORACE="" GOROOT="/usr/lib/golang" GOTMPDIR="" GOTOOLDIR="/usr/lib/golang/pkg/tool/linux_amd64" GCCGO="gccgo" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" PKG_CONFIG="pkg-config" GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build502356231=/tmp/go-build -gno-record-gcc-switches" Output

What did you do?

I write a program to test pprof heap but I found someting inconsisitent.

go  tool pprof  http://127.0.0.1:8200/debug/pprof/heap?debug=1
Fetching profile over HTTP from http://127.0.0.1:8200/debug/pprof/heap?debug=1
Saved profile in /data/tbase/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: inuse_space
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) top
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%
(pprof) traces
Type: inuse_space
-----------+-------------------------------------------------------
     bytes:  2kB
         0   runtime/pprof.writeHeapInternal
             runtime/pprof.writeHeap
             runtime/pprof.(*Profile).WriteTo
             net/http/pprof.handler.ServeHTTP
             net/http/pprof.Index
             net/http.HandlerFunc.ServeHTTP
             net/http.(*ServeMux).ServeHTTP
             net/http.serverHandler.ServeHTTP
             net/http.(*conn).serve
             runtime.goexit
-----------+-------------------------------------------------------
     bytes:  136kB
         0   compress/flate.(*compressor).init
             compress/flate.NewWriter
             compress/gzip.(*Writer).Write
             runtime/pprof.(*profileBuilder).build
             runtime/pprof.writeHeapProto
             runtime/pprof.writeHeapInternal
             runtime/pprof.writeHeap
             runtime/pprof.(*Profile).WriteTo
             net/http/pprof.handler.ServeHTTP
             net/http/pprof.Index
             net/http.HandlerFunc.ServeHTTP
             net/http.(*ServeMux).ServeHTTP
             net/http.serverHandler.ServeHTTP
             net/http.(*conn).serve
             runtime.goexit
-----------+-------------------------------------------------------
     bytes:  8kB
         0   bytes.makeSlice
             bytes.(*Buffer).grow
             bytes.(*Buffer).ReadFrom
             io/ioutil.readAll
             io/ioutil.ReadFile
             runtime/pprof.(*profileBuilder).readMapping
             runtime/pprof.newProfileBuilder
             runtime/pprof.writeHeapProto
             runtime/pprof.writeHeapInternal
             runtime/pprof.writeHeap
             runtime/pprof.(*Profile).WriteTo
             net/http/pprof.handler.ServeHTTP
             net/http/pprof.Index
             net/http.HandlerFunc.ServeHTTP
             net/http.(*ServeMux).ServeHTTP
             net/http.serverHandler.ServeHTTP
             net/http.(*conn).serve
             runtime.goexit
-----------+-------------------------------------------------------
     bytes:  1kB
         0   sync.(*Pool).pinSlow
             sync.(*Pool).pin
             sync.(*Pool).Get
             net/http.newBufioWriterSize
             net/http.(*conn).readRequest
             net/http.(*conn).serve
             runtime.goexit
-----------+-------------------------------------------------------
     bytes:  2.25kB
         0   compress/flate.(*huffmanEncoder).generate
             compress/flate.(*huffmanBitWriter).writeBlockDynamic
             compress/flate.(*compressor).encSpeed
             compress/flate.(*compressor).close
             compress/flate.(*Writer).Close
             compress/gzip.(*Writer).Close
             runtime/pprof.(*profileBuilder).build
             runtime/pprof.writeHeapProto
             runtime/pprof.writeHeapInternal
             runtime/pprof.writeHeap
             runtime/pprof.(*Profile).WriteTo
             net/http/pprof.handler.ServeHTTP
             net/http/pprof.Index
             net/http.HandlerFunc.ServeHTTP
             net/http.(*ServeMux).ServeHTTP
             net/http.serverHandler.ServeHTTP
             net/http.(*conn).serve
             runtime.goexit
-----------+-------------------------------------------------------
     bytes:  648kB
         0   compress/flate.NewWriter
             compress/gzip.(*Writer).Write
             runtime/pprof.(*profileBuilder).build
             runtime/pprof.writeHeapProto
             runtime/pprof.writeHeapInternal
             runtime/pprof.writeHeap
             runtime/pprof.(*Profile).WriteTo
             net/http/pprof.handler.ServeHTTP
             net/http/pprof.Index
             net/http.HandlerFunc.ServeHTTP
             net/http.(*ServeMux).ServeHTTP
             net/http.serverHandler.ServeHTTP
             net/http.(*conn).serve
             runtime.goexit
-----------+-------------------------------------------------------
     bytes:  1GB
         0   main.Test1
             main.Test
             runtime.goexit
-----------+-------------------------------------------------------
(pprof) 

What did you expect to see?

Top command shows nothing but traces command shows there are many memory usage.
And when I used top only to found out it did not cause that much memory.

25586_ tbase 20 0 1670.0m 36.7m 3.0m S 16.3 0.2 30:13.38 test

Here is my program.

package main

import (
                _ "net/http/pprof"
                "time"
                "net/http"
                "strconv"
                "log"
)

func Test1() {
        a := make([]byte,1024 *1024 * 1024)
        for i := 1 ; i < 1024 * 1024 * 1024 ; i++ {
                a[i] = 'c'
        }
        for true {
                time.Sleep(10000);
        }
}

func Test() {

        Test1();

}

func main() {

        go func() {
                server_addr := ":" + strconv.Itoa(8200)
                log.Println(http.ListenAndServe(server_addr, nil))
        }()

        go Test()

        for true {
                time.Sleep(10000);
        }
}

How can I explain their difference?

What did you see instead?

@q2683252 q2683252 changed the title perf heap command top and traces show diffent data. perf heap command top and traces show different data. Sep 11, 2019
@mdempsky mdempsky changed the title perf heap command top and traces show different data. cmd/pprof: heap command top and traces show different data Sep 11, 2019
@hyangah
Copy link
Contributor

@hyangah hyangah commented Sep 13, 2019

The trace command output indicates all sampled allocations were already garbage collected (0s on the left column indicates 0 samples.)

In particular, the big slice allocated in Test1 was sampled but when the trace was collected, it was already gc'd.

     bytes:  1GB
         0   main.Test1
             main.Test
             runtime.goexit

The top command presents only inuse_space (not garbage collected) samples in this case and there is a message No samples were found with the default sample value type. If you want to know the allocation history throughout the program execution, alloc_space sample_index option or -alloc_space flag will be helpful.

I think this is working as intended, but let me know if it makes sense to you. This bug may indicate insufficient documentation or the current documentation is hard to find.

@hyangah
Copy link
Contributor

@hyangah hyangah commented Sep 16, 2019

@q2683252 Is it ok to close this issue?

@gopherbot
Copy link

@gopherbot gopherbot commented Oct 16, 2019

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@gopherbot gopherbot closed this Oct 16, 2019
@golang golang locked and limited conversation to collaborators Oct 15, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
3 participants
You can’t perform that action at this time.