From cd8d7efc9669f2536bf1282ed734d18ebed2b53e Mon Sep 17 00:00:00 2001 From: congqixia Date: Wed, 19 Mar 2025 18:10:13 +0800 Subject: [PATCH] enhance: [2.5] Add an extra parameter for slow log (#40759) Cherry-pick from master pr: #40758 Related to #40756 Signed-off-by: Congqi Xia --- internal/proxy/impl.go | 39 ++++++++++++++++---------- pkg/util/paramtable/component_param.go | 11 ++++++++ 2 files changed, 35 insertions(+), 15 deletions(-) diff --git a/internal/proxy/impl.go b/internal/proxy/impl.go index eb75b013fd..2116d8fb60 100644 --- a/internal/proxy/impl.go +++ b/internal/proxy/impl.go @@ -3127,13 +3127,10 @@ func (node *Proxy) search(ctx context.Context, request *milvuspb.SearchRequest, defer func() { span := tr.ElapseSpan() - if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) { + if span >= paramtable.Get().ProxyCfg.SlowLogSpanInSeconds.GetAsDuration(time.Second) { log.Info(rpcSlow(method), zap.Uint64("guarantee_timestamp", qt.GetGuaranteeTimestamp()), zap.Int64("nq", qt.SearchRequest.GetNq()), zap.Duration("duration", span)) - metrics.ProxySlowQueryCount.WithLabelValues( - strconv.FormatInt(paramtable.GetNodeID(), 10), - metrics.SearchLabel, - ).Inc() + // WebUI slow query shall use slow log as well. user, _ := GetCurUserFromContext(ctx) traceID := "" if sp != nil { @@ -3143,6 +3140,12 @@ func (node *Proxy) search(ctx context.Context, request *milvuspb.SearchRequest, node.slowQueries.Add(qt.BeginTs(), metricsinfo.NewSlowQueryWithSearchRequest(request, user, span, traceID)) } } + if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) { + metrics.ProxySlowQueryCount.WithLabelValues( + strconv.FormatInt(paramtable.GetNodeID(), 10), + metrics.SearchLabel, + ).Inc() + } }() log.Debug(rpcReceived(method)) @@ -3360,12 +3363,9 @@ func (node *Proxy) hybridSearch(ctx context.Context, request *milvuspb.HybridSea defer func() { span := tr.ElapseSpan() - if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) { + if span >= paramtable.Get().ProxyCfg.SlowLogSpanInSeconds.GetAsDuration(time.Second) { log.Info(rpcSlow(method), zap.Uint64("guarantee_timestamp", qt.GetGuaranteeTimestamp()), zap.Duration("duration", span)) - metrics.ProxySlowQueryCount.WithLabelValues( - strconv.FormatInt(paramtable.GetNodeID(), 10), - metrics.HybridSearchLabel, - ).Inc() + // WebUI slow query shall use slow log as well. user, _ := GetCurUserFromContext(ctx) traceID := "" if sp != nil { @@ -3375,6 +3375,12 @@ func (node *Proxy) hybridSearch(ctx context.Context, request *milvuspb.HybridSea node.slowQueries.Add(qt.BeginTs(), metricsinfo.NewSlowQueryWithSearchRequest(newSearchReq, user, span, traceID)) } } + if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) { + metrics.ProxySlowQueryCount.WithLabelValues( + strconv.FormatInt(paramtable.GetNodeID(), 10), + metrics.HybridSearchLabel, + ).Inc() + } }() log.Debug(rpcReceived(method)) @@ -3645,7 +3651,7 @@ func (node *Proxy) query(ctx context.Context, qt *queryTask, sp trace.Span) (*mi defer func() { span := tr.ElapseSpan() - if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) { + if span >= paramtable.Get().ProxyCfg.SlowLogSpanInSeconds.GetAsDuration(time.Second) { log.Info( rpcSlow(method), zap.String("expr", request.Expr), @@ -3653,10 +3659,7 @@ func (node *Proxy) query(ctx context.Context, qt *queryTask, sp trace.Span) (*mi zap.Uint64("travel_timestamp", request.TravelTimestamp), zap.Uint64("guarantee_timestamp", qt.GetGuaranteeTimestamp()), zap.Duration("duration", span)) - metrics.ProxySlowQueryCount.WithLabelValues( - strconv.FormatInt(paramtable.GetNodeID(), 10), - metrics.QueryLabel, - ).Inc() + // WebUI slow query shall use slow log as well. user, _ := GetCurUserFromContext(ctx) traceID := "" if sp != nil { @@ -3667,6 +3670,12 @@ func (node *Proxy) query(ctx context.Context, qt *queryTask, sp trace.Span) (*mi node.slowQueries.Add(qt.BeginTs(), metricsinfo.NewSlowQueryWithQueryRequest(request, user, span, traceID)) } } + if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) { + metrics.ProxySlowQueryCount.WithLabelValues( + strconv.FormatInt(paramtable.GetNodeID(), 10), + metrics.QueryLabel, + ).Inc() + } }() if err := node.sched.dqQueue.Enqueue(qt); err != nil { diff --git a/pkg/util/paramtable/component_param.go b/pkg/util/paramtable/component_param.go index 32ec0c3dcb..5806268013 100644 --- a/pkg/util/paramtable/component_param.go +++ b/pkg/util/paramtable/component_param.go @@ -1387,6 +1387,7 @@ type proxyConfig struct { GracefulStopTimeout ParamItem `refreshable:"true"` SlowQuerySpanInSeconds ParamItem `refreshable:"true"` + SlowLogSpanInSeconds ParamItem `refreshable:"true"` QueryNodePoolingSize ParamItem `refreshable:"false"` } @@ -1833,6 +1834,16 @@ please adjust in embedded Milvus: false`, } p.SlowQuerySpanInSeconds.Init(base.mgr) + p.SlowLogSpanInSeconds = ParamItem{ + Key: "proxy.slowLogSpanInSeconds", + Version: "2.5.8", + Doc: "query whose executed time exceeds the `slowLogSpanInSeconds` will have slow log, in seconds.", + DefaultValue: "1", + FallbackKeys: []string{"proxy.slowQuerySpanInSeconds"}, + Export: false, + } + p.SlowLogSpanInSeconds.Init(base.mgr) + p.QueryNodePoolingSize = ParamItem{ Key: "proxy.queryNodePooling.size", Version: "2.4.7",