Merge pull request #87740 from jennybuckley/rate-limit-log

Log when client rate limiter latency is very high at a lower log level

Kubernetes-commit: 9de57634738cfd13bee5e29494e120cc2f24212c

Godeps/Godeps.json

@@ -348,7 +348,7 @@
 		},
 		{
 			"ImportPath": "k8s.io/api",
-			"Rev": "bb84ecda436d"
+			"Rev": "3d77e12e1dcd"
 		},
 		{
 			"ImportPath": "k8s.io/apimachinery",

go.mod

@@ -28,7 +28,7 @@ require (
 	golang.org/x/oauth2 v0.0.0-20190604053449-0f29369cfe45
 	golang.org/x/time v0.0.0-20190308202827-9d24e82272b4
 	google.golang.org/appengine v1.5.0 // indirect
-	k8s.io/api v0.0.0-20200131032352-bb84ecda436d
+	k8s.io/api v0.0.0-20200202064633-3d77e12e1dcd
 	k8s.io/apimachinery v0.0.0-20200131032148-f30c02351710
 	k8s.io/klog v1.0.0
 	k8s.io/utils v0.0.0-20191217005138-9e5e9d854fcc
@@ -38,6 +38,6 @@ require (
 replace (
 	golang.org/x/sys => golang.org/x/sys v0.0.0-20190813064441-fde4db37ae7a // pinned to release-branch.go1.13
 	golang.org/x/tools => golang.org/x/tools v0.0.0-20190821162956-65e3620a7ae7 // pinned to release-branch.go1.13
-	k8s.io/api => k8s.io/api v0.0.0-20200131032352-bb84ecda436d
+	k8s.io/api => k8s.io/api v0.0.0-20200202064633-3d77e12e1dcd
 	k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20200131032148-f30c02351710
 )

go.sum

@@ -190,7 +190,7 @@ gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10=
 gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.0-20190106161140-3f1c8253044a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
-k8s.io/api v0.0.0-20200131032352-bb84ecda436d/go.mod h1:C9pVgJPZJ6Vya/pyuzhd4qytMYQjdxSscnExZvbavLo=
+k8s.io/api v0.0.0-20200202064633-3d77e12e1dcd/go.mod h1:C9pVgJPZJ6Vya/pyuzhd4qytMYQjdxSscnExZvbavLo=
 k8s.io/apimachinery v0.0.0-20200131032148-f30c02351710/go.mod h1:f7PPp70QzCGGLJHvCtiN2lePa9CdVddeAdL5w7NdrrU=
 k8s.io/gengo v0.0.0-20190128074634-0689ccc1d7d6/go.mod h1:ezvh/TsK7cY6rbqRK0oQQ8IAqLxYwwyPxAX1Pzy0ii0=
 k8s.io/klog v0.0.0-20181102134211-b9b56d5dfc92/go.mod h1:Gq+BEi5rUBO/HRz0bTSXDUcqjScdoY3a9IHpCEIOOfk=

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) {