furyhawk/milvus
1
0
Fork 0
mirror of https://github.com/milvus-io/milvus.git synced 2026-07-21 10:15:43 +00:00
Code Issues Packages Projects Releases Wiki Activity

enhance: slow log improvement (#47070)

Browse Source 
issue: https://github.com/milvus-io/milvus/issues/44452

this pr merged slowLogSpanInSeconds and slowQuerySpanInSeconds config,
and ensure that failed requests will not trigger a slow log.

---------

Signed-off-by: Buqian Zheng <zhengbuqian@gmail.com>
This commit is contained in:
Buqian Zheng
2026-01-15 15:47:28 +08:00
committed by GitHub
parent 2572770870
commit b7c65f3f71
3 changed files with 31 additions and 28 deletions
Download Patch File Download Diff File Expand all files Collapse all files
configs/milvus.yaml
+1 -1
View File
@@ -361,7 +361,7 @@ proxy:
connectionClientInfoTTLSeconds: 86400 # inactive client info TTL duration, in seconds
maxConnectionNum: 10000 # the max client info numbers that proxy should manage, avoid too many client infos
gracefulStopTimeout: 30 # seconds. force stop node without graceful stop
slowQuerySpanInSeconds: 5 # query whose executed time exceeds the `slowQuerySpanInSeconds` can be considered slow, in seconds.
slowQuerySpanInSeconds: 1 # threshold for slow query detection in seconds. For Search/HybridSearch requests, the time is divided by nq for more accurate per-query measurement. Triggers slow log, WebUI display, and metrics.
queryNodePooling:
size: 10 # the size for shardleader(querynode) client pool
partialResultRequiredDataRatio: 1 # partial result required data ratio, default to 1 which means disable partial result, otherwise, it will be used as the minimum data ratio for partial result
internal/proxy/impl.go
+28 -14
View File
@@ -3044,16 +3044,19 @@ func (node *Proxy) search(ctx context.Context, request *milvuspb.SearchRequest,
zap.Bool("useDefaultConsistency", request.GetUseDefaultConsistency()),
)
succeeded := false
defer func() {
if !succeeded {
return
}
span := tr.ElapseSpan()
spanPerNq := span
if qt.SearchRequest.GetNq() > 0 {
spanPerNq = span / time.Duration(qt.SearchRequest.GetNq())
}
if spanPerNq >= paramtable.Get().ProxyCfg.SlowLogSpanInSeconds.GetAsDuration(time.Second) {
if spanPerNq >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) {
log.Info(rpcSlow(method), zap.Uint64("guarantee_timestamp", qt.GetGuaranteeTimestamp()),
zap.Int64("nq", qt.SearchRequest.GetNq()), zap.Duration("duration", span), zap.Duration("durationPerNq", spanPerNq))
// WebUI slow query shall use slow log as well.
user, _ := GetCurUserFromContext(ctx)
traceID := ""
if sp != nil {
@@ -3062,8 +3065,6 @@ func (node *Proxy) search(ctx context.Context, request *milvuspb.SearchRequest,
if node.slowQueries != nil {
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,
@@ -3166,6 +3167,7 @@ func (node *Proxy) search(ctx context.Context, request *milvuspb.SearchRequest,
metrics.ProxyReportValue.WithLabelValues(nodeID, hookutil.OpTypeSearch, dbName, username).Add(float64(v))
}
}
succeeded = true
return qt.result, qt.resultSizeInsufficient, qt.isTopkReduce, qt.isRecallEvaluation, nil
}
@@ -3275,11 +3277,23 @@ func (node *Proxy) hybridSearch(ctx context.Context, request *milvuspb.HybridSea
zap.Stringer("dsls", &hybridSearchRequestExprLogger{HybridSearchRequest: request}),
)
succeeded := false
defer func() {
if !succeeded {
return
}
span := tr.ElapseSpan()
if span >= paramtable.Get().ProxyCfg.SlowLogSpanInSeconds.GetAsDuration(time.Second) {
log.Info(rpcSlow(method), zap.Uint64("guarantee_timestamp", qt.GetGuaranteeTimestamp()), zap.Duration("duration", span))
// WebUI slow query shall use slow log as well.
spanPerNq := span
var totalNq int64
for _, subReq := range request.GetRequests() {
totalNq += subReq.GetNq()
}
if totalNq > 0 {
spanPerNq = span / time.Duration(totalNq)
}
if spanPerNq >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) {
log.Info(rpcSlow(method), zap.Uint64("guarantee_timestamp", qt.GetGuaranteeTimestamp()),
zap.Int64("totalNq", totalNq), zap.Duration("duration", span), zap.Duration("durationPerNq", spanPerNq))
user, _ := GetCurUserFromContext(ctx)
traceID := ""
if sp != nil {
@@ -3288,8 +3302,6 @@ func (node *Proxy) hybridSearch(ctx context.Context, request *milvuspb.HybridSea
if node.slowQueries != nil {
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,
@@ -3391,6 +3403,7 @@ func (node *Proxy) hybridSearch(ctx context.Context, request *milvuspb.HybridSea
metrics.ProxyReportValue.WithLabelValues(nodeID, hookutil.OpTypeHybridSearch, dbName, username).Add(float64(v))
}
}
succeeded = true
return qt.result, qt.resultSizeInsufficient, qt.isTopkReduce, nil
}
@@ -3721,9 +3734,13 @@ func (node *Proxy) query(ctx context.Context, qt *queryTask, sp trace.Span) (*mi
tr := timerecord.NewTimeRecorder(method)
succeeded := false
defer func() {
if !succeeded {
return
}
span := tr.ElapseSpan()
if span >= paramtable.Get().ProxyCfg.SlowLogSpanInSeconds.GetAsDuration(time.Second) {
if span >= paramtable.Get().ProxyCfg.SlowQuerySpanInSeconds.GetAsDuration(time.Second) {
log.Info(
rpcSlow(method),
zap.String("expr", request.Expr),
@@ -3731,18 +3748,14 @@ 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))
// WebUI slow query shall use slow log as well.
user, _ := GetCurUserFromContext(ctx)
traceID := ""
if sp != nil {
traceID = sp.SpanContext().TraceID().String()
}
if node.slowQueries != nil {
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,
@@ -3796,6 +3809,7 @@ func (node *Proxy) query(ctx context.Context, qt *queryTask, sp trace.Span) (*mi
).Observe(float64(tr.ElapseSpan().Milliseconds()))
}
succeeded = true
return qt.result, qt.storageCost, nil
}
pkg/util/paramtable/component_param.go
+2 -13
View File
@@ -1930,7 +1930,6 @@ type proxyConfig struct {
GracefulStopTimeout ParamItem `refreshable:"true"`
SlowQuerySpanInSeconds ParamItem `refreshable:"true"`
SlowLogSpanInSeconds ParamItem `refreshable:"true"`
QueryNodePoolingSize ParamItem `refreshable:"false"`
HybridSearchRequeryPolicy ParamItem `refreshable:"true"`
@@ -2432,22 +2431,12 @@ Disabled if the value is less or equal to 0.`,
p.SlowQuerySpanInSeconds = ParamItem{
Key: "proxy.slowQuerySpanInSeconds",
Version: "2.3.11",
Doc: "query whose executed time exceeds the `slowQuerySpanInSeconds` can be considered slow, in seconds.",
DefaultValue: "5",
Doc: "threshold for slow query detection in seconds. For Search/HybridSearch requests, the time is divided by nq for more accurate per-query measurement. Triggers slow log, WebUI display, and metrics.",
DefaultValue: "1",
Export: true,
}
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. If request type is search, the query time will be divided by nq number.",
DefaultValue: "1",
FallbackKeys: []string{"proxy.slowQuerySpanInSeconds"},
Export: false,
}
p.SlowLogSpanInSeconds.Init(base.mgr)
p.QueryNodePoolingSize = ParamItem{
Key: "proxy.queryNodePooling.size",
Version: "2.4.7",