From 9ee80cfbdc72f36490bc5762acf3ef08d41b8698 Mon Sep 17 00:00:00 2001
From: jennybuckley <jennybuckley@google.com>
Date: Fri, 31 Jan 2020 16:17:22 -0800
Subject: [PATCH] Log when client side rate limiter latency is very high

Kubernetes-commit: 82a68be304338f0bee9ed9bdc99a7acc1895e102
---
 rest/request.go | 37 ++++++++++++++++++++++++++++++++++++-
 1 file changed, 36 insertions(+), 1 deletion(-)

diff --git a/rest/request.go b/rest/request.go
index 545f15db..6b3db4aa 100644
--- a/rest/request.go
+++ b/rest/request.go
@@ -30,6 +30,7 @@ import (
 	"reflect"
 	"strconv"
 	"strings"
+	"sync"
 	"time"
 
 	"golang.org/x/net/http2"
@@ -51,6 +52,9 @@ var (
 	// throttled (via the provided rateLimiter) for more than longThrottleLatency will
 	// be logged.
 	longThrottleLatency = 50 * time.Millisecond
+
+	// extraLongThrottleLatency defines the threshold for logging requests at log level 2.
+	extraLongThrottleLatency = 1 * time.Second
 )
 
 // HTTPClient is an interface for testing a request object.
@@ -547,13 +551,44 @@ func (r *Request) tryThrottle(ctx context.Context) error {
 
 	err := r.rateLimiter.Wait(ctx)
 
-	if latency := time.Since(now); latency > longThrottleLatency {
+	latency := time.Since(now)
+	if latency > longThrottleLatency {
 		klog.V(3).Infof("Throttling request took %v, request: %s:%s", latency, r.verb, r.URL().String())
 	}
+	if latency > extraLongThrottleLatency {
+		globalThrottledLogger.Log(2, fmt.Sprintf("Throttling request took %v, request: %s:%s", latency, r.verb, r.URL().String()))
+	}
 
 	return err
 }
 
+type throttledLogger struct {
+	logTimeLock    sync.RWMutex
+	lastLogTime    time.Time
+	minLogInterval time.Duration
+}
+
+var globalThrottledLogger = &throttledLogger{
+	minLogInterval: 1 * time.Second,
+}
+
+func (b *throttledLogger) Log(level klog.Level, message string) {
+	if bool(klog.V(level)) {
+		if func() bool {
+			b.logTimeLock.RLock()
+			defer b.logTimeLock.RUnlock()
+			return time.Since(b.lastLogTime) > b.minLogInterval
+		}() {
+			b.logTimeLock.Lock()
+			defer b.logTimeLock.Unlock()
+			if time.Since(b.lastLogTime) > b.minLogInterval {
+				klog.V(level).Info(message)
+				b.lastLogTime = time.Now()
+			}
+		}
+	}
+}
+
 // Watch attempts to begin watching the requested location.
 // Returns a watch.Interface, or an error.
 func (r *Request) Watch(ctx context.Context) (watch.Interface, error) {