Improve query log in QueryNode (#17268)

Signed-off-by: Nbigsheeper <yihao.dai@zilliz.com>

internal/querynode/impl.go

@@ -579,7 +579,12 @@ func (node *QueryNode) Search(ctx context.Context, req *queryPb.SearchRequest) (
 		return failRet, nil
 	}
 
-	log.Debug("Received SearchRequest", zap.String("vchannel", req.GetDmlChannel()), zap.Int64s("segmentIDs", req.GetSegmentIDs()))
+	log.Debug("Received SearchRequest",
+		zap.Int64("msgID", req.GetReq().GetBase().GetMsgID()),
+		zap.String("vChannel", req.GetDmlChannel()),
+		zap.Int64s("segmentIDs", req.GetSegmentIDs()),
+		zap.Uint64("guaranteeTimestamp", req.GetReq().GetGuaranteeTimestamp()),
+		zap.Uint64("timeTravel", req.GetReq().GetTravelTimestamp()))
 
 	if node.queryShardService == nil {
 		failRet.Status.Reason = "queryShardService is nil"
@@ -739,7 +744,13 @@ func (node *QueryNode) Query(ctx context.Context, req *queryPb.QueryRequest) (*i
 		failRet.Status.Reason = msgQueryNodeIsUnhealthy(Params.QueryNodeCfg.GetNodeID())
 		return failRet, nil
 	}
-	log.Debug("Received QueryRequest", zap.String("vchannel", req.GetDmlChannel()), zap.Int64s("segmentIDs", req.GetSegmentIDs()))
+
+	log.Debug("Received QueryRequest",
+		zap.Int64("msgID", req.GetReq().GetBase().GetMsgID()),
+		zap.String("vChannel", req.GetDmlChannel()),
+		zap.Int64s("segmentIDs", req.GetSegmentIDs()),
+		zap.Uint64("guaranteeTimestamp", req.GetReq().GetGuaranteeTimestamp()),
+		zap.Uint64("timeTravel", req.GetReq().GetTravelTimestamp()))
 
 	if node.queryShardService == nil {
 		failRet.Status.Reason = "queryShardService is nil"

internal/querynode/query_shard.go

@@ -127,15 +127,7 @@ func (tp tsType) String() string {
 	return ""
 }
 
-func (q *queryShard) getServiceableTime(tp tsType) (Timestamp, error) {
-	var channel string
-	switch tp {
-	case tsTypeDML:
-		channel = q.channel
-	case tsTypeDelta:
-		channel = q.deltaChannel
-	}
-
+func (q *queryShard) getServiceableTime(channel Channel) (Timestamp, error) {
 	ts, err := q.tSafeReplica.getTSafe(channel)
 	if err != nil {
 		return 0, err

internal/querynode/query_shard_test.go

@@ -127,11 +127,11 @@ func TestQueryShard_getServiceableTime(t *testing.T) {
 	err = updateQueryShardTSafe(qs, timestamp)
 	assert.NoError(t, err)
 
-	dmlTimestamp, err := qs.getServiceableTime(tsTypeDML)
+	dmlTimestamp, err := qs.getServiceableTime(qs.channel)
 	assert.NoError(t, err)
 	assert.Equal(t, timestamp, dmlTimestamp)
 
-	deltaTimestamp, err := qs.getServiceableTime(tsTypeDelta)
+	deltaTimestamp, err := qs.getServiceableTime(qs.deltaChannel)
 	assert.NoError(t, err)
 	assert.Equal(t, timestamp, deltaTimestamp)
 }

internal/querynode/task_read.go

@@ -139,15 +139,13 @@ func (b *baseReadTask) Ready() (bool, error) {
 	if b.Timeout() {
 		return false, fmt.Errorf("deadline exceed")
 	}
-	var err error
-	var tType tsType
+	var channel Channel
 	if b.DataScope == querypb.DataScope_Streaming {
-		tType = tsTypeDML
+		channel = b.QS.channel
 	} else if b.DataScope == querypb.DataScope_Historical {
-		tType = tsTypeDelta
-	}
-	if err != nil {
-		return false, err
+		channel = b.QS.deltaChannel
+	} else {
+		return false, fmt.Errorf("unexpected dataScope %s", b.DataScope.String())
 	}
 
 	if _, released := b.QS.collection.getReleaseTime(); released {
@@ -155,9 +153,9 @@ func (b *baseReadTask) Ready() (bool, error) {
 		return false, fmt.Errorf("collection has been released, taskID = %d, collectionID = %d", b.ID(), b.CollectionID)
 	}
 
-	serviceTime, err2 := b.QS.getServiceableTime(tType)
-	if err2 != nil {
-		return false, fmt.Errorf("failed to get service timestamp, taskID = %d, collectionID = %d, err=%w", b.ID(), b.CollectionID, err2)
+	serviceTime, err := b.QS.getServiceableTime(channel)
+	if err != nil {
+		return false, fmt.Errorf("failed to get service timestamp, taskID = %d, collectionID = %d, err=%w", b.ID(), b.CollectionID, err)
 	}
 	guaranteeTs := b.GuaranteeTimestamp
 	gt, _ := tsoutil.ParseTS(guaranteeTs)
@@ -167,9 +165,17 @@ func (b *baseReadTask) Ready() (bool, error) {
 			zap.Any("collectionID", b.CollectionID),
 			zap.Any("sm.GuaranteeTimestamp", gt),
 			zap.Any("serviceTime", st),
-			zap.Any("delta seconds", (guaranteeTs-serviceTime)/(1000*1000*1000)),
+			zap.Any("delta milliseconds", gt.Sub(st).Milliseconds()),
+			zap.Any("channel", channel),
 			zap.Any("msgID", b.ID()))
 		return false, nil
 	}
+	log.Debug("query msg can do",
+		zap.Any("collectionID", b.CollectionID),
+		zap.Any("sm.GuaranteeTimestamp", gt),
+		zap.Any("serviceTime", st),
+		zap.Any("delta milliseconds", gt.Sub(st).Milliseconds()),
+		zap.Any("channel", channel),
+		zap.Any("msgID", b.ID()))
 	return true, nil
 }