diff --git a/staging/src/k8s.io/client-go/transport/round_trippers.go b/staging/src/k8s.io/client-go/transport/round_trippers.go index 818fd52d6e5..2abbcc1c448 100644 --- a/staging/src/k8s.io/client-go/transport/round_trippers.go +++ b/staging/src/k8s.io/client-go/transport/round_trippers.go @@ -17,9 +17,12 @@ limitations under the License. package transport import ( + "crypto/tls" "fmt" "net/http" + "net/http/httptrace" "strings" + "sync" "time" "golang.org/x/oauth2" @@ -68,7 +71,7 @@ func HTTPWrappersForConfig(config *Config, rt http.RoundTripper) (http.RoundTrip func DebugWrappers(rt http.RoundTripper) http.RoundTripper { switch { case bool(klog.V(9).Enabled()): - rt = NewDebuggingRoundTripper(rt, DebugCurlCommand, DebugURLTiming, DebugResponseHeaders) + rt = NewDebuggingRoundTripper(rt, DebugCurlCommand, DebugDetailedTiming, DebugResponseHeaders) case bool(klog.V(8).Enabled()): rt = NewDebuggingRoundTripper(rt, DebugJustURL, DebugRequestHeaders, DebugResponseStatus, DebugResponseHeaders) case bool(klog.V(7).Enabled()): @@ -314,6 +317,14 @@ type requestInfo struct { ResponseHeaders http.Header ResponseErr error + muTrace sync.Mutex // Protect trace fields + DNSLookup time.Duration + Dialing time.Duration + GetConnection time.Duration + TLSHandshake time.Duration + ServerProcessing time.Duration + ConnectionReused bool + Duration time.Duration } @@ -374,6 +385,8 @@ const ( DebugResponseStatus // DebugResponseHeaders will add to the debug output the HTTP response headers. DebugResponseHeaders + // DebugDetailedTiming will add to the debug output the duration of the HTTP requests events. + DebugDetailedTiming ) // NewDebuggingRoundTripper allows to display in the logs output debug information @@ -445,6 +458,74 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e } startTime := time.Now() + + if rt.levels[DebugDetailedTiming] { + var getConn, dnsStart, dialStart, tlsStart, serverStart time.Time + var host string + trace := &httptrace.ClientTrace{ + // DNS + DNSStart: func(info httptrace.DNSStartInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + dnsStart = time.Now() + host = info.Host + }, + DNSDone: func(info httptrace.DNSDoneInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.DNSLookup = time.Now().Sub(dnsStart) + klog.Infof("HTTP Trace: DNS Lookup for %s resolved to %v", host, info.Addrs) + }, + // Dial + ConnectStart: func(network, addr string) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + dialStart = time.Now() + }, + ConnectDone: func(network, addr string, err error) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.Dialing = time.Now().Sub(dialStart) + if err != nil { + klog.Infof("HTTP Trace: Dial to %s:%s failed: %v", network, addr, err) + } else { + klog.Infof("HTTP Trace: Dial to %s:%s succeed", network, addr) + } + }, + // TLS + TLSHandshakeStart: func() { + tlsStart = time.Now() + }, + TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.TLSHandshake = time.Now().Sub(tlsStart) + }, + // Connection (it can be DNS + Dial or just the time to get one from the connection pool) + GetConn: func(hostPort string) { + getConn = time.Now() + }, + GotConn: func(info httptrace.GotConnInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.GetConnection = time.Now().Sub(getConn) + reqInfo.ConnectionReused = info.Reused + }, + // Server Processing (time since we wrote the request until first byte is received) + WroteRequest: func(info httptrace.WroteRequestInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + serverStart = time.Now() + }, + GotFirstResponseByte: func() { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.ServerProcessing = time.Now().Sub(serverStart) + }, + } + req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) + } + response, err := rt.delegatedRoundTripper.RoundTrip(req) reqInfo.Duration = time.Since(startTime) @@ -453,6 +534,24 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e if rt.levels[DebugURLTiming] { klog.Infof("%s %s %s in %d milliseconds", reqInfo.RequestVerb, reqInfo.RequestURL, reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond)) } + if rt.levels[DebugDetailedTiming] { + stats := "" + if !reqInfo.ConnectionReused { + stats += fmt.Sprintf(`DNSLookup %d ms Dial %d ms TLSHandshake %d ms`, + reqInfo.DNSLookup.Nanoseconds()/int64(time.Millisecond), + reqInfo.Dialing.Nanoseconds()/int64(time.Millisecond), + reqInfo.TLSHandshake.Nanoseconds()/int64(time.Millisecond), + ) + } else { + stats += fmt.Sprintf(`GetConnection %d ms`, reqInfo.GetConnection.Nanoseconds()/int64(time.Millisecond)) + } + if reqInfo.ServerProcessing != 0 { + stats += fmt.Sprintf(` ServerProcessing %d ms`, reqInfo.ServerProcessing.Nanoseconds()/int64(time.Millisecond)) + } + stats += fmt.Sprintf(` Duration %d ms`, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond)) + klog.Infof("HTTP Statistics: %s", stats) + } + if rt.levels[DebugResponseStatus] { klog.Infof("Response Status: %s in %d milliseconds", reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond)) }