v3rpc: print expensive request info in UnaryInterceptor
@@ -34,6 +34,7 @@ import (
const (
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
}
+ 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)
