Merge pull request #12086 from tangcong/print-expensive-request-v3rpc

v3rpc: Log expensive request in UnaryInterceptor

CHANGELOG-3.5.md

@@ -131,6 +131,7 @@ Note that any `etcd_debugging_*` metrics are experimental and subject to change.
 - Add [etcd --auth-token-ttl](https://github.com/etcd-io/etcd/pull/11980) flag to customize `simpleTokenTTL` settings.
 - Improve [runtime.FDUsage objects malloc of Memory Usage and CPU Usage](https://github.com/etcd-io/etcd/pull/11986).
 - Improve [mvcc.watchResponse channel Memory Usage](https://github.com/etcd-io/etcd/pull/11987).
+- Log [expensive request info in UnaryInterceptor](https://github.com/etcd-io/etcd/pull/12086).
 
 ### Package `embed`
 

etcdserver/api/v3rpc/interceptor.go

@@ -33,7 +33,8 @@ import (
 )
 
 const (
-	maxNoLeaderCnt = 3
+	maxNoLeaderCnt          = 3
+	warnUnaryRequestLatency = 300 * time.Millisecond
 )
 
 type streamsMap struct {
@@ -75,7 +76,7 @@ func newLogUnaryInterceptor(s *etcdserver.EtcdServer) grpc.UnaryServerIntercepto
 		startTime := time.Now()
 		resp, err := handler(ctx, req)
 		lg := s.Logger()
-		if lg != nil && lg.Core().Enabled(zap.DebugLevel) { // only acquire stats if debug level is enabled
+		if lg != nil { // acquire stats if debug level is enabled or request is expensive
 			defer logUnaryRequestStats(ctx, lg, info, startTime, req, resp)
 		}
 		return resp, err
@@ -84,6 +85,16 @@ func newLogUnaryInterceptor(s *etcdserver.EtcdServer) grpc.UnaryServerIntercepto
 
 func logUnaryRequestStats(ctx context.Context, lg *zap.Logger, info *grpc.UnaryServerInfo, startTime time.Time, req interface{}, resp interface{}) {
 	duration := time.Since(startTime)
+	var enabledDebugLevel, expensiveRequest bool
+	if lg.Core().Enabled(zap.DebugLevel) {
+		enabledDebugLevel = true
+	}
+	if duration > warnUnaryRequestLatency {
+		expensiveRequest = true
+	}
+	if !enabledDebugLevel && !expensiveRequest {
+		return
+	}
 	remote := "No remote client info."
 	peerInfo, ok := peer.FromContext(ctx)
 	if ok {
@@ -158,7 +169,11 @@ func logUnaryRequestStats(ctx context.Context, lg *zap.Logger, info *grpc.UnaryS
 		respSize = -1
 	}
 
-	logGenericRequestStats(lg, startTime, duration, remote, responseType, reqCount, reqSize, respCount, respSize, reqContent)
+	if enabledDebugLevel {
+		logGenericRequestStats(lg, startTime, duration, remote, responseType, reqCount, reqSize, respCount, respSize, reqContent)
+	} else if expensiveRequest {
+		logExpensiveRequestStats(lg, startTime, duration, remote, responseType, reqCount, reqSize, respCount, respSize, reqContent)
+	}
 }
 
 func logGenericRequestStats(lg *zap.Logger, startTime time.Time, duration time.Duration, remote string, responseType string,
@@ -176,6 +191,21 @@ func logGenericRequestStats(lg *zap.Logger, startTime time.Time, duration time.D
 	)
 }
 
+func logExpensiveRequestStats(lg *zap.Logger, startTime time.Time, duration time.Duration, remote string, responseType string,
+	reqCount int64, reqSize int, respCount int64, respSize int, reqContent string) {
+	lg.Warn("request stats",
+		zap.Time("start time", startTime),
+		zap.Duration("time spent", duration),
+		zap.String("remote", remote),
+		zap.String("response type", responseType),
+		zap.Int64("request count", reqCount),
+		zap.Int("request size", reqSize),
+		zap.Int64("response count", respCount),
+		zap.Int("response size", respSize),
+		zap.String("request content", reqContent),
+	)
+}
+
 func newStreamInterceptor(s *etcdserver.EtcdServer) grpc.StreamServerInterceptor {
 	smap := monitorLeader(s)