runtime/pprof: fetching profile results in EOF - 1.8rc2

[ardan-bkennedy]

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

go version go1.8rc2 darwin/amd64

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

macOS Sierra - version 10.12.2

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/bill/code/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_v/4r515ktx08g5yr6dgkxhfyfr0000gn/T/go-build345861231=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

I have a simple web application used for teaching how to use pprof:
https://github.com/ardanlabs/gotraining/tree/master/topics/profiling/project

I will build and run this web application in a terminal session:
cd $GOPATH/src/github.com/ardanlabs/gotraining/topics/profiling/project
go build
./project

I will put load on the application in a new terminal session with the hey tool:
hey -m POST -c 8 -n 1000000 "http://localhost:5000/search?term=politics&cnn=on&bbc=on&nyt=on"

The service will request new versions of the three different rss feeds every 15 seconds and use a cached version in-between. The application is using the XML decoder and templates.

Once the load has started I run the pprof tool in a new terminal session:
cd $GOPATH/src/github.com/ardanlabs/gotraining/topics/profiling/project
go tool pprof ./project http://localhost:5000/debug/pprof/profile

What did you expect to see?

In previous versions of Go I would enter into the pprof interactive mode.

What did you see instead?

Fetching profile from http://localhost:5000/debug/pprof/profile
Please wait... (30s)
http fetch http://localhost:5000/debug/pprof/profile: Get http://localhost:5000/debug/pprof/profile: EOF

Notes

I have tried these steps with a different but very simple web service and everything worked. I also asked others in the community if they were having problems and they said no. So there may be something specific with this code that is causing the issue?

[josharian]

If you do curl -vv http://localhost:5000/debug/pprof/profile, what does it say? What happens if you manually try to dump the profile?

[vcabbage]

This appears to be due to interactions between http.Server.ReadTimeout, http.Server.WriteTimeout and http.CloseNotifier.

@ardan-bkennedy's application configures the server as so:

	host := "localhost:5000"
	readTimeout := 10 * time.Second
	writeTimeout := 30 * time.Second

	// Create a new server and set timeout values.
	s := manners.NewWithServer(&http.Server{
		Addr:           host,
		Handler:        http.DefaultServeMux,
		ReadTimeout:    readTimeout,
		WriteTimeout:   writeTimeout,
		MaxHeaderBytes: 1 << 20,
	})

Adding some debug lines to the /debug/pprof/profile handler we can observe the effect of the timeouts:

--- a/src/net/http/pprof/pprof.go
+++ b/src/net/http/pprof/pprof.go
@@ -86,17 +86,21 @@ func sleep(w http.ResponseWriter, d time.Duration) {
        }
        select {
        case <-time.After(d):
+               fmt.Println("Sleep Exit Method: time elapsed")
        case <-clientGone:
+               fmt.Println("Sleep Exit Method: CloseNotify")
        }
 }

 // Profile responds with the pprof-formatted cpu profile.
 // The package initialization registers it as /debug/pprof/profile.
 func Profile(w http.ResponseWriter, r *http.Request) {
+       start := time.Now()
        sec, _ := strconv.ParseInt(r.FormValue("seconds"), 10, 64)
        if sec == 0 {
                sec = 30
        }
+       fmt.Println("Requested Profile Duration (seconds):", sec)

        // Set Content Type assuming StartCPUProfile will work,
        // because if it does it starts writing.
@@ -112,6 +116,7 @@ func Profile(w http.ResponseWriter, r *http.Request) {
        }
        sleep(w, time.Duration(sec)*time.Second)
        pprof.StopCPUProfile()
+       fmt.Println("Actual Duration:", time.Since(start))
 }

Go 1.7:

# go build -a && ./project
2017/01/22 13:30:12.954432 service.go:64: Listening on: localhost:5000
Requested Profile Duration (seconds): 30
Sleep Exit Method: CloseNotify
Actual Duration: 10.003911307s

1. Request made to /debug/pprof/profile.
2. Handler defaults to a 30 second profile.
3. CloseNotify channel fires after ~10s (due to ReadTimeout)
4. Handler exits.

Go 1.8:

# go1.8rc2 build -a && ./project
2017/01/22 13:34:01.961320 service.go:64: Listening on: localhost:5000
Requested Profile Duration (seconds): 30
Sleep Exit Method: time elapsed
Actual Duration: 30.004416723s

1. Request made to /debug/pprof/profile.
2. Handler defaults to a 30 second profile.
3. 30 second sleep elapses.

---

In the 1.8 case the handler actually sleeps for ~30 seconds and the WriteTimeout is hit causing the EOF to the client.

The 1.7 behavior with CloseNofity appears to be #9524, which is still open but seems to be fixed by https://golang.org/cl/34813/.

Increasing the WriteTimeout to 31 seconds or decreasing the profile time (go tool pprof -seconds 29 ./project http://localhost:5000/debug/pprof/profile) allows the profile to work correctly in 1.8, which I believe to be the correct behavior.

[bradfitz]

Seems like everything is working as documented, then:

https://beta.golang.org/pkg/net/http/#Server.WriteTimeout

    // WriteTimeout is the maximum duration before timing out
    // writes of the response. It is reset whenever a new
    // request's header is read. Like ReadTimeout, it does not
    // let Handlers make decisions on a per-request basis.
    WriteTimeout time.Duration

Closing. Please reopen if we misunderstood.

[ardan-bkennedy]

@vcabbage thank you for taking the time to figure all that out. It makes total sense now. Thank you as well @bradfitz.