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: fetching profile results in EOF - 1.8rc2 #18746

Closed
ardan-bkennedy opened this issue Jan 22, 2017 · 4 comments
Closed

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

ardan-bkennedy opened this issue Jan 22, 2017 · 4 comments
Labels
FrozenDueToAge
Milestone
Go1.8Maybe

Comments

@ardan-bkennedy
Copy link

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?
@ardan-bkennedy ardan-bkennedy changed the title Fetching profile results in EOF Fetching profile results in EOF - 1.8rc2 Jan 22, 2017
@josharian josharian changed the title Fetching profile results in EOF - 1.8rc2 runtime/pprof: fetching profile results in EOF - 1.8rc2 Jan 22, 2017
@josharian josharian added this to the Go1.8Maybe milestone Jan 22, 2017
@josharian
Copy link
Contributor

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

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

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.

This was referenced Jan 22, 2017
Closed
Closed
@ardan-bkennedy
Copy link
Author

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

@golang golang locked and limited conversation to collaborators Jan 23, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.8Maybe
Development

No branches or pull requests
5 participants
@bradfitz @josharian @ardan-bkennedy @gopherbot @vcabbage