Add time records for search path (#20924)

Signed-off-by: yah01 <yang.cen@zilliz.com>

Signed-off-by: yah01 <yang.cen@zilliz.com>

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
 }

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,

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()