profiling webserver with pprof and router middleware

[skalde...@gmail.com]

Hey guiys, I posted a StackOF question two days ago, but so far nobody was able to help me!

I am trying to profile my web server I wrote, but my pprof does not contain any data about the handler func.  

I am using the httprouter package by julienschmidt, and want to simply benchmark one of my handlers and see the pprof profile for that. For the benchmarking, I am using go-wrk  

I set up my web server and pprof like this:

   

 // Configure the server
 server := &http.Server{
     Addr:    ":4000",
     Handler: router,
 }


 go func() {
     log.Println(http.ListenAndServe(":6060", nil))
 }()


 // Start the server
 err = server.ListenAndServe()
 if err != nil {
     panic(err)
 }

The router is initialized like this:

 

  // Create the httprouter
 router := httprouter.New()
 // Register all handlers
 router.GET("/entities/:type/map", h.UseHandler(&h.ApiGetEntitiesMapRequest{}, p))

And my handler looks like this:

   

 func (req ApiGetEntitiesMapRequest) Handle(r *http.Request, hrp httprouter.Params, p Params) (interface{}, error) {
     test := make([]string, 0)
     for i := 0; i < 1000; i++ {
         test = append(test, "1")
         test = append(test, "2")
         // Ensure pprof has some time to collect its data
         time.Sleep(10)
     }
     return test, nil
}

This handler is just a test, where I dynamically append a lot of elements to a slice. The reason for that is, I wanted to test whether these dynamic allocations are represented in the heap profile of pprof.

Now, what I did was: 

 

 - Start my server  

 - execute **go tool pprof http://localhost:6060/debug/pprof/heap** in my terminal  

 - then benchmark my handler by executing **go-wrk -no-c -d 5 http://localhost:4000/entities/object/map**  

The request works and my benchmark also reports everything correctly. However, when I type **png** in the pprof terminal, I get this graph:

The graph does not contain any information about my handler and the costly heap allocations I did in my handler. What am I doing wrong?

[Karan Chaudhary]

From the top of my head,  shouldn't the benchmark be done when traffic is being sent to the server and not before it is sent?

[skalde...@gmail.com]

The go tool pprof command is interactive, so I thought it is enough type 'png' to get the image after the benchmark is run

I tested to start go tool pprof now as well during and after the benchmark -> nothing changes

[skalde...@gmail.com]

Does noone have an idea? :(

[Karan Chaudhary]

Are you just trying to see how heap allocation can be seen using debug/pprof?  

Maybe you're allocating too less.  Try to allocate exponentialy.

package main

import (

"log"

"net/http"

"time"

_ "net/http/pprof"

)

func expalloc() {

x := make([]int, 0)

for i := 0; i < 10; i++ {

x = append(x, i)

x = append(x, x...)

}

time.Sleep(10 * time.Second)

}

func main() {

go func() {

log.Println(http.ListenAndServe("localhost:6060", nil))

}()

expalloc()

}

Allocations on my machine (reduce 50 to smaller number as the program might go out of memory):

[Karan Chaudhary]

Attaching png:

[skalde...@gmail.com]

Specifically, I wanted to see heap allocations generated by incoming requests, so I can optimize my handler functions

I will write a more basic webserver example to see if I can produce the result I am expecting

[skalde...@gmail.com]

I finally found the problem!!!

Since I am using a custom mux, I needed to register the pprof handler funcs to my custom router

router.HandlerFunc(http.MethodGet, "/debug/pprof/", pprof.Index)

router.HandlerFunc(http.MethodGet, "/debug/pprof/cmdline", pprof.Cmdline)

router.HandlerFunc(http.MethodGet, "/debug/pprof/profile", pprof.Profile)

router.HandlerFunc(http.MethodGet, "/debug/pprof/symbol", pprof.Symbol)

router.HandlerFunc(http.MethodGet, "/debug/pprof/trace", pprof.Trace)

router.Handler(http.MethodGet, "/debug/pprof/goroutine", pprof.Handler("goroutine"))

router.Handler(http.MethodGet, "/debug/pprof/heap", pprof.Handler("heap"))

router.Handler(http.MethodGet,"/debug/pprof/threadcreate", pprof.Handler("threadcreate"))

router.Handler(http.MethodGet,"/debug/pprof/block", pprof.Handler("block"))

Then, I started my benchmark (go-wrk) and then I started the pprof tool (go tool pprof http://localhost:4000/debug/pprof/heap)

After hitting "web", I was granted this wonderful graph: 

[Karan Chaudhary]

Great find!