Merge pull request #105156 from aojea/clientgo_trace

Enhance client-go url timing logging with http statistics

Kubernetes-commit: b7da9ef49f82ac8b54d28931a5b3e1de30accfd3

go.mod

@@ -30,8 +30,8 @@ require (
 	golang.org/x/term v0.0.0-20210615171337-6886f2dfbf5b
 	golang.org/x/time v0.0.0-20210723032227-1f47c861a9ac
 	google.golang.org/protobuf v1.26.0
-	k8s.io/api v0.0.0-20211001003357-dd4141958dfc
+	k8s.io/api v0.0.0-20211005163402-965a3d4efac6
-	k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc
+	k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a
 	k8s.io/klog/v2 v2.20.0
 	k8s.io/kube-openapi v0.0.0-20210817084001-7fbd8d59e5b8
 	k8s.io/utils v0.0.0-20210930125809-cb0fa318a74b
@@ -40,6 +40,6 @@ require (
 )
 
 replace (
-	k8s.io/api => k8s.io/api v0.0.0-20211001003357-dd4141958dfc
+	k8s.io/api => k8s.io/api v0.0.0-20211005163402-965a3d4efac6
-	k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc
+	k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a
 )

go.sum

@@ -599,10 +599,10 @@ honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWh
 honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg=
 honnef.co/go/tools v0.0.1-2020.1.3/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9vFzvIQ3k=
 honnef.co/go/tools v0.0.1-2020.1.4/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9vFzvIQ3k=
-k8s.io/api v0.0.0-20211001003357-dd4141958dfc h1:mEvk8nUryhzsFO3gvz1GOCHKAk9SwmCy1E+TfTtrPdM=
+k8s.io/api v0.0.0-20211005163402-965a3d4efac6 h1:4nid4gaGt4QFtlvh0BuRJukvljt+Mwp7mhFhtNl5A80=
-k8s.io/api v0.0.0-20211001003357-dd4141958dfc/go.mod h1:X/EFj3T8/b6pT7Vu0CQfs8hKQGD/NpK6nituBPxPypM=
+k8s.io/api v0.0.0-20211005163402-965a3d4efac6/go.mod h1:uigk499NtRe0ine9Jz9mxVwAjascSPD/Ojn9xYSyB58=
-k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc h1:xWJbWTw1QtGvoHnsdF1oI10d2gEBl2yqipw/m1DQjLU=
+k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a h1:vUbAbtv8pmpeY1rOEQZjy/ALaYwNKdUi3d6pyq9B7Os=
-k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc/go.mod h1:RAdi3McqM+9tkYHOyceb4XOeJWm9BCAF4BhZki5iiok=
+k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a/go.mod h1:RAdi3McqM+9tkYHOyceb4XOeJWm9BCAF4BhZki5iiok=
 k8s.io/gengo v0.0.0-20200413195148-3a45101e95ac/go.mod h1:ezvh/TsK7cY6rbqRK0oQQ8IAqLxYwwyPxAX1Pzy0ii0=
 k8s.io/klog/v2 v2.0.0/go.mod h1:PBfzABfn139FHAV07az/IF9Wp1bkk3vpT2XSJ76fSDE=
 k8s.io/klog/v2 v2.20.0 h1:tlyxlSvd63k7axjhuchckaRJm+a92z5GSOrTOQY5sHw=

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"
@@ -69,7 +72,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()):
@@ -320,6 +323,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
 }
 
@@ -380,6 +391,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
@@ -451,6 +464,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)
 
@@ -459,6 +540,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))
 	}