From ec3aef1f3e7385d1998aa21a33037a347e559c1c Mon Sep 17 00:00:00 2001 From: yah01 Date: Fri, 2 Dec 2022 11:39:17 +0800 Subject: [PATCH] Add time records for search path (#20924) Signed-off-by: yah01 Signed-off-by: yah01 --- internal/querynode/task_read.go | 8 +++++--- internal/querynode/task_search.go | 2 +- internal/util/timerecord/time_recorder.go | 12 +++++++++++- 3 files changed, 17 insertions(+), 5 deletions(-) diff --git a/internal/querynode/task_read.go b/internal/querynode/task_read.go index f9b2653225..26a7e66c1a 100644 --- a/internal/querynode/task_read.go +++ b/internal/querynode/task_read.go @@ -75,9 +75,9 @@ func (b *baseReadTask) SetStep(step TaskStep) { switch step { case TaskStepEnqueue: b.queueDur = 0 - b.tr.Record("enqueueStart") + b.tr.Record("enqueue done") case TaskStepPreExecute: - b.queueDur = b.tr.Record("enqueueEnd") + b.queueDur = b.tr.Record("start to process") } } @@ -109,6 +109,8 @@ func (b *baseReadTask) Notify(err error) { switch b.step { case TaskStepEnqueue: b.queueDur = b.tr.Record("enqueueEnd") + case TaskStepPostExecute: + b.tr.Record("execute task done") } b.baseTask.Notify(err) } @@ -175,6 +177,6 @@ func (b *baseReadTask) Ready() (bool, error) { zap.Any("delta milliseconds", gt.Sub(st).Milliseconds()), zap.Any("channel", channel), zap.Any("msgID", b.ID())) - b.waitTsDur = b.waitTSafeTr.ElapseSpan() + b.waitTsDur = b.waitTSafeTr.Elapse("wait for tsafe done") return true, nil } diff --git a/internal/querynode/task_search.go b/internal/querynode/task_search.go index 1c04ab123f..3391133163 100644 --- a/internal/querynode/task_search.go +++ b/internal/querynode/task_search.go @@ -413,7 +413,7 @@ func newSearchTask(ctx context.Context, src *querypb.SearchRequest) (*searchTask TravelTimestamp: src.Req.GetTravelTimestamp(), GuaranteeTimestamp: src.Req.GetGuaranteeTimestamp(), TimeoutTimestamp: src.Req.GetTimeoutTimestamp(), - tr: timerecord.NewTimeRecorder("searchTask"), + tr: timerecord.NewTimeRecorderWithTrace(ctx, "searchTask"), DataScope: src.GetScope(), }, iReq: src.Req, diff --git a/internal/util/timerecord/time_recorder.go b/internal/util/timerecord/time_recorder.go index 4a640ecb14..e744ae5bb0 100644 --- a/internal/util/timerecord/time_recorder.go +++ b/internal/util/timerecord/time_recorder.go @@ -17,6 +17,7 @@ import ( "time" "github.com/milvus-io/milvus/internal/log" + "github.com/milvus-io/milvus/internal/util/trace" "go.uber.org/zap" ) @@ -25,7 +26,6 @@ type TimeRecorder struct { header string start time.Time last time.Time - ctx context.Context } // NewTimeRecorder creates a new TimeRecorder @@ -37,6 +37,16 @@ func NewTimeRecorder(header string) *TimeRecorder { } } +// NewTimeRecorderWithCtx creates a new TimeRecorder with context's traceID, +func NewTimeRecorderWithTrace(ctx context.Context, header string) *TimeRecorder { + traceID, _, _ := trace.InfoFromContext(ctx) + return &TimeRecorder{ + header: fmt.Sprintf("%s(%s)", header, traceID), + start: time.Now(), + last: time.Now(), + } +} + // RecordSpan returns the duration from last record func (tr *TimeRecorder) RecordSpan() time.Duration { curr := time.Now()