How to measure function run times-CodePudding

In a golang web server I want to measure times taken by some http controller. I am calling time.Now() before calling controller function, and time.Since() after controller function returns. But if it has long remote io request that takes 1 second, or the process is throttled, or controller is parallelized with goroutines - then that time will be not exactly what I want.

If we assume analogy to bash time command - then I am getting real time with this technique:

time go build

real    0m5,204s
user    0m12,012s
sys 0m2,043s

How can I measure user and sys times for a function run(preferably for a goroutine plus its forked children) in a golang program (preferably with standard packages)?

this is my profiler implementation. How can i extend it with sys and user time per goroutine?

const HeaderCost = "Cost"

// Timed middleware will set Cost header in http response
func Timed(h http.Handler) http.HandlerFunc {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        h.ServeHTTP(&responseWriterWithTimer{
            ResponseWriter: w,
            headerWritten:  false,
            startedAt:      time.Now(),
        }, r)
    })
}

type responseWriterWithTimer struct {
    http.ResponseWriter
    headerWritten bool
    startedAt     time.Time
}

func (w *responseWriterWithTimer) WriteHeader(statusCode int) {
    w.Header().Set(
        HeaderCost,
        strconv.FormatFloat(
            time.Since(w.startedAt).Seconds(),
            'g',
            64,
            64,
        ),
    )
    w.ResponseWriter.WriteHeader(statusCode)
    w.headerWritten = true
}

func (w *responseWriterWithTimer) Write(b []byte) (int, error) {
    if !w.headerWritten {
        w.WriteHeader(http.StatusOK)
    }
    return w.ResponseWriter.Write(b)
}

CodePudding user response：

If you want to do basic instrumentation at runtime, you can wrap your handlers to measure their execution time:

func perfMiddleware(h http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        t := time.Now()
        h.ServeHTTP(w, r)
        log.Printf("handler took %s", time.Since(t))
    })
}

You could expose this more easily using expvar. Going beyond this, there are also numerous instrumentation/telemetry/APM libraries available for Go if you look for them, along with metrics management solutions like the TICK stack, Datadog, and so on.

As for the real, user, and sys data output by time, these are posix measures that don't perfectly apply to instrumenting a Go HTTP handler (or any other unit of code at runtime), for a number of reasons:

goroutines have no parent/child relationship; all are equal peers, so there is no metric of the time taken by "children" of your handler.
most of the I/O is handled within the stdlib, which isn't instrumented to this level (and instrumentation at this level would have a non-negligible performance impact of its own)

You can of course instrument each piece individually, which is often more useful; for example, instrument your HTTP handlers, as well as any code that is making its own external requests, in order to measure the performance of each component. From this you can analyze the data and get a much clearer picture of what is taking time, in order to address any performance issues you find.

CodePudding user response：

If you want to measure something in isolation, benchmarks are probably exactly what you're after.

If you're trying to measure a http.Handler, you can use httptest.NewRecorder and httptest.NewRequest to create a new response writer and request object and just invoke the handler directly inside your benchmark.

func BenchmnarkHttpHandler(b*testing.B) {

  req := httptest.NewRequest("GET", "/foo", nil)

  myHandler := thingtotest.Handler{}

  for n := 0; n < b.N; n   {
     myHandler.ServeHTTP(httptest.NewRecorder(), req);
  }
}

CodePudding user response：

How can I measure user and sys times for a function run

You cannot. That distinction is not an observable for Go functions.

(But honestly: Measuring them is of no real use and doesn't make much sense. This sound like a XY problem.)