diff --git a/CHANGELOG-3.5.md b/CHANGELOG-3.5.md index ef86cddd5b4..8b9e488f8fb 100644 --- a/CHANGELOG-3.5.md +++ b/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` diff --git a/etcdserver/api/v3rpc/interceptor.go b/etcdserver/api/v3rpc/interceptor.go index 5bae935df50..45ea5d734fd 100644 --- a/etcdserver/api/v3rpc/interceptor.go +++ b/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)