From 041a812ba00c17fa3150d66a03e0e8c46d75527d Mon Sep 17 00:00:00 2001 From: poornas Date: Thu, 18 Jul 2019 15:29:17 -0700 Subject: [PATCH] trace api: add call stats to trace (#7915) Stats such as call latency, bytes received and sent have been added --- cmd/http-tracer.go | 52 +++++++++++++++++++++++++++++++++------------- pkg/trace/trace.go | 16 ++++++++++---- 2 files changed, 50 insertions(+), 18 deletions(-) diff --git a/cmd/http-tracer.go b/cmd/http-tracer.go index b59df2655..c904ed6e4 100644 --- a/cmd/http-tracer.go +++ b/cmd/http-tracer.go @@ -43,10 +43,16 @@ type recordRequest struct { logBody bool // Internal recording buffer buf bytes.Buffer + // request headers + headers http.Header + // total bytes read including header size + bytesRead int } func (r *recordRequest) Read(p []byte) (n int, err error) { n, err = r.Reader.Read(p) + r.bytesRead += n + if r.logBody { r.buf.Write(p[:n]) } @@ -55,6 +61,13 @@ func (r *recordRequest) Read(p []byte) (n int, err error) { } return n, err } +func (r *recordRequest) Size() int { + sz := r.bytesRead + for k, v := range r.headers { + sz += len(k) + len(v) + } + return sz +} // Return the bytes that were recorded. func (r *recordRequest) Data() []byte { @@ -80,13 +93,17 @@ type recordResponseWriter struct { statusCode int // Indicate if headers are written in the log headersLogged bool + // number of bytes written + bytesWritten int } // Write the headers into the given buffer -func writeHeaders(w io.Writer, statusCode int, headers http.Header) { - fmt.Fprintf(w, "%d %s\n", statusCode, http.StatusText(statusCode)) +func (r *recordResponseWriter) writeHeaders(w io.Writer, statusCode int, headers http.Header) { + n, _ := fmt.Fprintf(w, "%d %s\n", statusCode, http.StatusText(statusCode)) + r.bytesWritten += n for k, v := range headers { - fmt.Fprintf(w, "%s: %s\n", k, v[0]) + n, _ := fmt.Fprintf(w, "%s: %s\n", k, v[0]) + r.bytesWritten += n } } @@ -94,7 +111,7 @@ func writeHeaders(w io.Writer, statusCode int, headers http.Header) { func (r *recordResponseWriter) WriteHeader(i int) { r.statusCode = i if !r.headersLogged { - writeHeaders(&r.headers, i, r.ResponseWriter.Header()) + r.writeHeaders(&r.headers, i, r.ResponseWriter.Header()) r.headersLogged = true } r.ResponseWriter.WriteHeader(i) @@ -102,10 +119,11 @@ func (r *recordResponseWriter) WriteHeader(i int) { func (r *recordResponseWriter) Write(p []byte) (n int, err error) { n, err = r.ResponseWriter.Write(p) + r.bytesWritten += n if !r.headersLogged { // We assume the response code to be '200 OK' when WriteHeader() is not called, // that way following Golang HTTP response behavior. - writeHeaders(&r.headers, http.StatusOK, r.ResponseWriter.Header()) + r.writeHeaders(&r.headers, http.StatusOK, r.ResponseWriter.Header()) r.headersLogged = true } if (r.statusCode != http.StatusOK && r.statusCode != http.StatusPartialContent && r.statusCode != 0) || r.logBody { @@ -115,6 +133,10 @@ func (r *recordResponseWriter) Write(p []byte) (n int, err error) { return n, err } +func (r *recordResponseWriter) Size() int { + return r.bytesWritten +} + // Calls the underlying Flush. func (r *recordResponseWriter) Flush() { r.ResponseWriter.(http.Flusher).Flush() @@ -151,9 +173,17 @@ func getOpName(name string) (op string) { func Trace(f http.HandlerFunc, logBody bool, w http.ResponseWriter, r *http.Request) trace.Info { name := getOpName(runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name()) + // Setup a http request body recorder + reqHeaders := cloneHeader(r.Header) + reqHeaders.Set("Content-Length", strconv.Itoa(int(r.ContentLength))) + reqHeaders.Set("Host", r.Host) + for _, enc := range r.TransferEncoding { + reqHeaders.Add("Transfer-Encoding", enc) + } + var reqBodyRecorder *recordRequest t := trace.Info{FuncName: name} - reqBodyRecorder = &recordRequest{Reader: r.Body, logBody: logBody} + reqBodyRecorder = &recordRequest{Reader: r.Body, logBody: logBody, headers: reqHeaders} r.Body = ioutil.NopCloser(reqBodyRecorder) t.NodeName = r.Host if globalIsDistXL { @@ -164,14 +194,6 @@ func Trace(f http.HandlerFunc, logBody bool, w http.ResponseWriter, r *http.Requ t.NodeName = host } - // Setup a http request body recorder - reqHeaders := cloneHeader(r.Header) - reqHeaders.Set("Content-Length", strconv.Itoa(int(r.ContentLength))) - reqHeaders.Set("Host", r.Host) - for _, enc := range r.TransferEncoding { - reqHeaders.Add("Transfer-Encoding", enc) - } - rq := trace.RequestInfo{ Time: time.Now().UTC(), Method: r.Method, @@ -199,5 +221,7 @@ func Trace(f http.HandlerFunc, logBody bool, w http.ResponseWriter, r *http.Requ t.ReqInfo = rq t.RespInfo = rs + + t.CallStats = trace.CallStats{Latency: rs.Time.Sub(rq.Time), InputBytes: reqBodyRecorder.Size(), OutputBytes: respBodyRecorder.Size()} return t } diff --git a/pkg/trace/trace.go b/pkg/trace/trace.go index d2b4123bc..2ec9bed7d 100644 --- a/pkg/trace/trace.go +++ b/pkg/trace/trace.go @@ -24,10 +24,18 @@ import ( // Info - represents a trace record, additionally // also reports errors if any while listening on trace. type Info struct { - NodeName string `json:"nodename"` - FuncName string `json:"funcname"` - ReqInfo RequestInfo `json:"request"` - RespInfo ResponseInfo `json:"response"` + NodeName string `json:"nodename"` + FuncName string `json:"funcname"` + ReqInfo RequestInfo `json:"request"` + RespInfo ResponseInfo `json:"response"` + CallStats CallStats `json:"stats"` +} + +// CallStats records request stats +type CallStats struct { + InputBytes int `json:"inputbytes"` + OutputBytes int `json:"outputbytes"` + Latency time.Duration `json:"latency"` } // RequestInfo represents trace of http request