Refine the log of CalcDistance (#12371)

Signed-off-by: dragondriver <jiquan.long@zilliz.com>

internal/proxy/impl.go

@@ -1889,6 +1889,12 @@ func (node *Proxy) AlterAlias(ctx context.Context, request *milvuspb.AlterAliasR
 
 // CalcDistance calculates the distances between vectors.
 func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDistanceRequest) (*milvuspb.CalcDistanceResults, error) {
+	if !node.checkHealthy() {
+		return &milvuspb.CalcDistanceResults{
+			Status: unhealthyStatus(),
+		}, nil
+	}
+
 	param, _ := funcutil.GetAttrByKeyFromRepeatedKV("metric", request.GetParams())
 	metric, err := distance.ValidateMetricType(param)
 	if err != nil {
@@ -1900,6 +1906,10 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 		}, nil
 	}
 
+	sp, ctx := trace.StartSpanFromContextWithOperationName(ctx, "Proxy-CalcDistance")
+	defer sp.Finish()
+	traceID, _, _ := trace.InfoFromSpan(sp)
+
 	query := func(ids *milvuspb.VectorIDs) (*milvuspb.QueryResults, error) {
 		outputFields := []string{ids.FieldName}
 
@@ -1926,14 +1936,17 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 			qc:        node.queryCoord,
 			ids:       ids.IdArray,
 		}
-		log.Debug("calcDistance enqueue",
+
+		err := node.sched.dqQueue.Enqueue(qt)
+		if err != nil {
+			log.Debug("CalcDistance queryTask failed to enqueue",
+				zap.Error(err),
+				zap.String("traceID", traceID),
 				zap.String("role", Params.RoleName),
 				zap.String("db", queryRequest.DbName),
 				zap.String("collection", queryRequest.CollectionName),
 				zap.Any("partitions", queryRequest.PartitionNames))
 
-		err := node.sched.dqQueue.Enqueue(qt)
-		if err != nil {
 			return &milvuspb.QueryResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -1941,7 +1954,9 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 				},
 			}, err
 		}
-		log.Debug("calcDistance",
+
+		log.Debug("CalcDistance queryTask enqueued",
+			zap.String("traceID", traceID),
 			zap.String("role", Params.RoleName),
 			zap.Int64("msgID", qt.Base.MsgID),
 			zap.Uint64("timestamp", qt.Base.Timestamp),
@@ -1949,20 +1964,20 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 			zap.String("collection", queryRequest.CollectionName),
 			zap.Any("partitions", queryRequest.PartitionNames),
 			zap.Any("OutputFields", queryRequest.OutputFields))
-		defer func() {
-			log.Debug("calcDistance Done",
-				zap.Error(err),
-				zap.String("role", Params.RoleName),
-				zap.Int64("msgID", qt.Base.MsgID),
-				zap.Uint64("timestamp", qt.Base.Timestamp),
-				zap.String("db", queryRequest.DbName),
-				zap.String("collection", queryRequest.CollectionName),
-				zap.Any("partitions", queryRequest.PartitionNames),
-				zap.Any("OutputFields", queryRequest.OutputFields))
-		}()
 
 		err = qt.WaitToFinish()
 		if err != nil {
+			log.Debug("CalcDistance queryTask failed to WaitToFinish",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName),
+				zap.Int64("msgID", qt.Base.MsgID),
+				zap.Uint64("timestamp", qt.Base.Timestamp),
+				zap.String("db", queryRequest.DbName),
+				zap.String("collection", queryRequest.CollectionName),
+				zap.Any("partitions", queryRequest.PartitionNames),
+				zap.Any("OutputFields", queryRequest.OutputFields))
+
 			return &milvuspb.QueryResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -1970,8 +1985,9 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 				},
 			}, err
 		}
-		log.Debug("calcDistance Finished",
+
-			zap.Error(err),
+		log.Debug("CalcDistance queryTask Done",
+			zap.String("traceID", traceID),
 			zap.String("role", Params.RoleName),
 			zap.Int64("msgID", qt.Base.MsgID),
 			zap.Uint64("timestamp", qt.Base.Timestamp),
@@ -2060,13 +2076,25 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 		return nil, errors.New("failed to fetch vectors")
 	}
 
-	log.Debug("grpc calcDistance begin")
+	log.Debug("CalcDistance received",
+		zap.String("traceID", traceID),
+		zap.String("role", Params.RoleName),
+		zap.String("metric", metric))
 
 	vectorsLeft := request.GetOpLeft().GetDataArray()
 	opLeft := request.GetOpLeft().GetIdArray()
 	if opLeft != nil {
+		log.Debug("OpLeft IdArray not empty, Get vectors by id",
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		result, err := query(opLeft)
 		if err != nil {
+			log.Debug("Failed to get left vectors by id",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2075,8 +2103,17 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 			}, nil
 		}
 
+		log.Debug("OpLeft IdArray not empty, Get vectors by id done",
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		vectorsLeft, err = arrangeFunc(opLeft, result.FieldsData)
 		if err != nil {
+			log.Debug("Failed to re-arrange left vectors",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2084,13 +2121,22 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 				},
 			}, nil
 		}
+
+		log.Debug("Re-arrange left vectors done",
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
 	}
 
 	if vectorsLeft == nil {
+		msg := "Left vectors array is empty"
+		log.Debug(msg,
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		return &milvuspb.CalcDistanceResults{
 			Status: &commonpb.Status{
 				ErrorCode: commonpb.ErrorCode_UnexpectedError,
-				Reason:    "Left vectors array is empty",
+				Reason:    msg,
 			},
 		}, nil
 	}
@@ -2098,8 +2144,17 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 	vectorsRight := request.GetOpRight().GetDataArray()
 	opRight := request.GetOpRight().GetIdArray()
 	if opRight != nil {
+		log.Debug("OpRight IdArray not empty, Get vectors by id",
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		result, err := query(opRight)
 		if err != nil {
+			log.Debug("Failed to get right vectors by id",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2108,8 +2163,17 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 			}, nil
 		}
 
+		log.Debug("OpRight IdArray not empty, Get vectors by id done",
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		vectorsRight, err = arrangeFunc(opRight, result.FieldsData)
 		if err != nil {
+			log.Debug("Failed to re-arrange right vectors",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2117,22 +2181,36 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 				},
 			}, nil
 		}
+
+		log.Debug("Re-arrange right vectors done",
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
 	}
 
 	if vectorsRight == nil {
+		msg := "Right vectors array is empty"
+		log.Debug(msg,
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		return &milvuspb.CalcDistanceResults{
 			Status: &commonpb.Status{
 				ErrorCode: commonpb.ErrorCode_UnexpectedError,
-				Reason:    "Right vectors array is empty",
+				Reason:    msg,
 			},
 		}, nil
 	}
 
 	if vectorsLeft.Dim != vectorsRight.Dim {
+		msg := "Vectors dimension is not equal"
+		log.Debug(msg,
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		return &milvuspb.CalcDistanceResults{
 			Status: &commonpb.Status{
 				ErrorCode: commonpb.ErrorCode_UnexpectedError,
-				Reason:    "Vectors dimension is not equal",
+				Reason:    msg,
 			},
 		}, nil
 	}
@@ -2140,6 +2218,11 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 	if vectorsLeft.GetFloatVector() != nil && vectorsRight.GetFloatVector() != nil {
 		distances, err := distance.CalcFloatDistance(vectorsLeft.Dim, vectorsLeft.GetFloatVector().Data, vectorsRight.GetFloatVector().Data, metric)
 		if err != nil {
+			log.Debug("Failed to CalcFloatDistance",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2148,6 +2231,11 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 			}, nil
 		}
 
+		log.Debug("CalcFloatDistance done",
+			zap.Error(err),
+			zap.String("traceID", traceID),
+			zap.String("role", Params.RoleName))
+
 		return &milvuspb.CalcDistanceResults{
 			Status: &commonpb.Status{ErrorCode: commonpb.ErrorCode_Success, Reason: ""},
 			Array: &milvuspb.CalcDistanceResults_FloatDist{
@@ -2161,6 +2249,11 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 	if vectorsLeft.GetBinaryVector() != nil && vectorsRight.GetBinaryVector() != nil {
 		hamming, err := distance.CalcHammingDistance(vectorsLeft.Dim, vectorsLeft.GetBinaryVector(), vectorsRight.GetBinaryVector())
 		if err != nil {
+			log.Debug("Failed to CalcHammingDistance",
+				zap.Error(err),
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{
 					ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2170,6 +2263,10 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 		}
 
 		if metric == distance.HAMMING {
+			log.Debug("CalcHammingDistance done",
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{ErrorCode: commonpb.ErrorCode_Success, Reason: ""},
 				Array: &milvuspb.CalcDistanceResults_IntDist{
@@ -2183,6 +2280,11 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 		if metric == distance.TANIMOTO {
 			tanimoto, err := distance.CalcTanimotoCoefficient(vectorsLeft.Dim, hamming)
 			if err != nil {
+				log.Debug("Failed to CalcTanimotoCoefficient",
+					zap.Error(err),
+					zap.String("traceID", traceID),
+					zap.String("role", Params.RoleName))
+
 				return &milvuspb.CalcDistanceResults{
 					Status: &commonpb.Status{
 						ErrorCode: commonpb.ErrorCode_UnexpectedError,
@@ -2191,6 +2293,10 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 				}, nil
 			}
 
+			log.Debug("CalcTanimotoCoefficient done",
+				zap.String("traceID", traceID),
+				zap.String("role", Params.RoleName))
+
 			return &milvuspb.CalcDistanceResults{
 				Status: &commonpb.Status{ErrorCode: commonpb.ErrorCode_Success, Reason: ""},
 				Array: &milvuspb.CalcDistanceResults_FloatDist{
@@ -2207,6 +2313,11 @@ func (node *Proxy) CalcDistance(ctx context.Context, request *milvuspb.CalcDista
 		err = errors.New("cannot calculate distance between binary vectors and float vectors")
 	}
 
+	log.Debug("Failed to CalcDistance",
+		zap.Error(err),
+		zap.String("traceID", traceID),
+		zap.String("role", Params.RoleName))
+
 	return &milvuspb.CalcDistanceResults{
 		Status: &commonpb.Status{
 			ErrorCode: commonpb.ErrorCode_UnexpectedError,