debug: mw cost

ppzqh · Aug 15, 2024 · cd42b4b · cd42b4b
1 parent d4e163a
commit cd42b4b
Show file tree

Hide file tree

Showing 5 changed files with 16 additions and 1 deletion.
diff --git a/client/middlewares.go b/client/middlewares.go
@@ -48,10 +48,13 @@ func newProxyMW(prx proxy.ForwardProxy) endpoint.Middleware {
 	}
 	return func(next endpoint.Endpoint) endpoint.Endpoint {
 		return func(ctx context.Context, request, response interface{}) error {
+			klog.CtxInfof(ctx, "[DEBUG] newProxyMW start, time=%s", time.Now())
 			err := prx.ResolveProxyInstance(ctx)
 			if err != nil {
+				klog.Info("[DEBUG] newProxyMW finish, time=%s", time.Now())
 				return err
 			}
+			klog.CtxInfof(ctx, "[DEBUG] newProxyMW finish, time=%s", time.Now())
 			err = next(ctx, request, response)
 			return err
 		}
@@ -85,6 +88,7 @@ func newResolveMWBuilder(lbf *lbcache.BalancerFactory) endpoint.MiddlewareBuilde
 	return func(ctx context.Context) endpoint.Middleware {
 		return func(next endpoint.Endpoint) endpoint.Endpoint {
 			return func(ctx context.Context, request, response interface{}) error {
+				klog.CtxInfof(ctx, "[DEBUG] resolveMW start, time=%s", time.Now())
 				rpcInfo := rpcinfo.GetRPCInfo(ctx)
 
 				dest := rpcInfo.To()
@@ -120,6 +124,7 @@ func newResolveMWBuilder(lbf *lbcache.BalancerFactory) endpoint.MiddlewareBuilde
 					if ins == nil {
 						err = kerrors.ErrNoMoreInstance.WithCause(fmt.Errorf("last error: %w", lastErr))
 					} else {
+						klog.CtxInfof(ctx, "[DEBUG] resolveMW finish1, time=%s", time.Now())
 						remote.SetInstance(ins)
 						// TODO: generalize retry strategy
 						err = next(ctx, request, response)

diff --git a/client/option.go b/client/option.go
@@ -92,6 +92,7 @@ func WithMiddleware(mw endpoint.Middleware) Option {
 		return mw
 	}
 	return Option{F: func(o *client.Options, di *utils.Slice) {
+		klog.Infof("[DEBUG] configure mw, name=%s", utils.GetFuncName(mw))
 		di.Push(fmt.Sprintf("WithMiddleware(%+v)", utils.GetFuncName(mw)))
 		o.MWBs = append(o.MWBs, mwb)
 	}}
@@ -100,6 +101,7 @@ func WithMiddleware(mw endpoint.Middleware) Option {
 // WithMiddlewareBuilder adds middleware that depend on context for client to handle request
 func WithMiddlewareBuilder(mwb endpoint.MiddlewareBuilder) Option {
 	return Option{F: func(o *client.Options, di *utils.Slice) {
+		klog.Infof("[DEBUG] configure mwbuilder, name=%s", utils.GetFuncName(mwb))
 		di.Push(fmt.Sprintf("WithMiddlewareBuilder(%+v)", utils.GetFuncName(mwb)))
 		o.MWBs = append(o.MWBs, mwb)
 	}}

diff --git a/client/rpctimeout.go b/client/rpctimeout.go
@@ -97,6 +97,7 @@ func rpcTimeoutMW(mwCtx context.Context) endpoint.Middleware {
 
 	return func(next endpoint.Endpoint) endpoint.Endpoint {
 		return func(ctx context.Context, request, response interface{}) error {
+			klog.CtxInfof(ctx, "[DEBUG] rpcTimeoutMW start, time=%s", time.Now())
 			ri := rpcinfo.GetRPCInfo(ctx)
 			if ri.Config().InteractionMode() == rpcinfo.Streaming {
 				return next(ctx, request, response)

diff --git a/internal/mocks/proxy/proxy.go b/internal/mocks/proxy/proxy.go
diff --git a/pkg/circuitbreak/circuitbreak.go b/pkg/circuitbreak/circuitbreak.go
@@ -19,6 +19,8 @@ package circuitbreak
 import (
 	"context"
 	"errors"
+	"github.com/cloudwego/kitex/pkg/klog"
+	"time"
 
 	"github.com/bytedance/gopkg/cloud/circuitbreaker"
 
@@ -78,15 +80,19 @@ type Control struct {
 func NewCircuitBreakerMW(control Control, panel circuitbreaker.Panel) endpoint.Middleware {
 	return func(next endpoint.Endpoint) endpoint.Endpoint {
 		return func(ctx context.Context, request, response interface{}) (err error) {
+			klog.CtxInfof(ctx, "[DEBUG] NewCircuitBreakerMW start, time=%s", time.Now())
 			key, enabled := control.GetKey(ctx, request)
 			if !enabled {
+				klog.CtxInfof(ctx, "[DEBUG] NewCircuitBreakerMW finish1, time=%s", time.Now())
 				return next(ctx, request, response)
 			}
 
 			if !panel.IsAllowed(key) {
+				klog.CtxInfof(ctx, "[DEBUG] NewCircuitBreakerMW finish2, time=%s", time.Now())
 				return control.DecorateError(ctx, request, kerrors.ErrCircuitBreak)
 			}
 
+			klog.CtxInfof(ctx, "[DEBUG] NewCircuitBreakerMW finish3, time=%s", time.Now())
 			err = next(ctx, request, response)
 			RecordStat(ctx, request, response, err, key, &control, panel)
 			return