Merge pull request #105156 from aojea/clientgo_trace

Enhance client-go url timing logging with http statistics

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"
@@ -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))
 	}