search

milvus-io / milvus

A cloud-native vector database, storage for next generation AI applications
https://milvus.io
Apache License 2.0
30.4k stars 2.91k forks source link

[Bug]: milvus cannot find enough rows at growing segment when using vector range search #36508

Closed chyezh closed 1 month ago

chyezh commented 1 month ago

Is there an existing issue for this?

Environment

- Milvus version: master-58baeee8f115a5963160e10713a9843f5165bd1d
- Deployment mode(standalone or cluster): cluster
- MQ type(rocksmq, pulsar or kafka):   pulsar
- SDK version(e.g. pymilvus v2.0.0rc2):
- OS(Ubuntu or CentOS): 
- CPU/Memory: 
- GPU: 
- Others:

Current Behavior

[pytest : test] [gw3] [ 74%] FAILED testcases/test_vector_operations.py::TestSearchVector::test_search_vector_with_range_search[COSINE] 

[pytest : test] self = <test_vector_operations.TestSearchVector object at 0x7f126c3304f0>
[pytest : test] metric_type = 'COSINE'
[pytest : test] 
[pytest : test]     @pytest.mark.parametrize("metric_type", ["L2", "COSINE", "IP"])
[pytest : test]     def test_search_vector_with_range_search(self, metric_type):
[pytest : test]         """
[pytest : test]         Search a vector with range search with different metric type
[pytest : test]         """
[pytest : test]         name = gen_collection_name()
[pytest : test]         self.name = name
[pytest : test]         nb = 3000
[pytest : test]         dim = 128
[pytest : test]         limit = 100
[pytest : test]         schema_payload, data = self.init_collection(name, dim=dim, nb=nb, metric_type=metric_type)
[pytest : test]         vector_field = schema_payload.get("vectorField")
[pytest : test]         # search data
[pytest : test]         vector_to_search = preprocessing.normalize([np.array([random.random() for i in range(dim)])])[0].tolist()
[pytest : test]         training_data = [item[vector_field] for item in data]
[pytest : test]         distance_sorted = get_sorted_distance(training_data, [vector_to_search], metric_type)
[pytest : test]         r1, r2 = distance_sorted[0][nb//2], distance_sorted[0][nb//2+limit+int((0.2*limit))] # recall is not 100% so add 20% to make sure the range is correct
[pytest : test]         if metric_type == "L2":
[pytest : test]             r1, r2 = r2, r1
[pytest : test]         output_fields = get_common_fields_by_data(data, exclude_fields=[vector_field])
[pytest : test]         payload = {
[pytest : test]             "collectionName": name,
[pytest : test]             "data": [vector_to_search],
[pytest : test]             "outputFields": output_fields,
[pytest : test]             "limit": limit,
[pytest : test]             "offset": 0,
[pytest : test]             "searchParams": {
[pytest : test]                 "params": {
[pytest : test]                     "radius": r1,
[pytest : test]                     "range_filter": r2,
[pytest : test]                 }
[pytest : test]             }
[pytest : test]         }
[pytest : test]         rsp = self.vector_client.vector_search(payload)
[pytest : test]         assert rsp['code'] == 0
[pytest : test]         res = rsp['data']
[pytest : test]         logger.info(f"res: {len(res)}")
[pytest : test] >       assert len(res) == limit
[pytest : test] E       AssertionError: assert 96 == 100
[pytest : test] E        +  where 96 = len([{'address': '00731 Harmon Throughway\nNew Jeffrey, MI 66955', 'distance': 0.7582831, 'email': 'wsanford@example.net', 'id': 17272498216352, ...}, {'address': 'PSC 5494, Box 1508\nAPO AA 69546', 'distance': 0.7582805, 'email': 'lbarnett@example.org', 'id': 17272498215663, ...}, {'address': '62681 Cody Oval Suite 446\nEast Donaldstad, MT 62640', 'distance': 0.75826377, 'email': 'alicia75@example.org', 'id': 17272498211299, ...}, {'address': '860 Lisa Mission\nKimbury, WY 48822', 'distance': 0.75825155, 'email': 'andrearowland@example.com', 'id': 17272498217289, ...}, {'address': '806 Aaron Terrace\nSouth Paigefort, WY 14146', 'distance': 0.7582057, 'email': 'hbarber@example.com', 'id': 17272498231747, ...}, {'address': '0184 Knight Ranch\nWest Christopherberg, AS 15130', 'distance': 0.7581984, 'email': 'taylorelizabeth@example.net', 'id': 17272498251130, ...}, ...])

...

[pytest : test] [2024-09-25 07:37:07 - DEBUG - ci_test]: 
[pytest : test] method: post, 
[pytest : test] url: http://mdss-36465-2-py-pr-milvus.milvus-ci:19530/v2/vectordb/entities/search, 
[pytest : test] cost time: 0.049895286560058594, 
[pytest : test] header: {'Content-Type': 'application/json', 'Authorization': 'Bearer None', 'Accept-Type-Allow-Int64': 'true', 'RequestId': 'f001730a-7b10-11ef-9f0e-d2e8d5f8cb46'}, 
[pytest : test] payload: {
[pytest : test]     "collectionName": "test_collection_2024_09_25_07_36_54_815601RRyqiJvH",
[pytest : test]     "data": [
[pytest : test]         [
[pytest : test]             0.007345872755789358,
[pytest : test]             "...",
[pytest : test]             0.03757473784777673
[pytest : test]         ]
[pytest : test]     ],
[pytest : test]     "outputFields": [
[pytest : test]         "uid",
[pytest : test]         "id",
[pytest : test]         "text",
[pytest : test]         "json",
[pytest : test]         "name",
[pytest : test]         "email",
[pytest : test]         "phone_number",
[pytest : test]         "address"
[pytest : test]     ],
[pytest : test]     "limit": 100,
[pytest : test]     "offset": 0,
[pytest : test]     "searchParams": {
[pytest : test]         "params": {
[pytest : test]             "radius": 0.75634765625,
[pytest : test]             "range_filter": 0.75830078125
[pytest : test]         }
[pytest : test]     }
[pytest : test] }, 
[pytest : test] response: {"code":0,"cost":0,"data":[{"address":"00731 Harmon Throughway\nNew Jeffrey, MI 66955","distance":0.7582831,"email":"wsanford@example.net","id":17272498216352,"json":{"address":"87110 Olivia Roads Apt...x339","text":"Only manage send lot industry born international. Able dog policy later simple she little. Total fear relationship real national run light.\nBut business lawyer natural man.","uid":42}]} (milvus.py:77)

Expected Behavior

No response

Steps To Reproduce

No response

Milvus Log

client: https://jenkins.milvus.io:18080/blue/rest/organizations/jenkins/pipelines/Milvus%20HA%20CI/branches/PR-36465/runs/2/nodes/107/steps/139/log/?start=0 server: https://grafana-4am.zilliz.cc/explore?panes=%7B%22Z8Q%22:%7B%22datasource%22:%22vhI6Vw67k%22,%22queries%22:%5B%7B%22refId%22:%22A%22,%22expr%22:%22%7Bnamespace%3D%5C%22milvus-ci%5C%22,pod%3D~%5C%22mdss-36465-2-py-pr-milvus.%2A%5C%22%7D%7C%3D%5C%22452787834070627086%5C%22%22,%22queryType%22:%22range%22,%22datasource%22:%7B%22type%22:%22loki%22,%22uid%22:%22vhI6Vw67k%22%7D,%22editorMode%22:%22code%22%7D%5D,%22range%22:%7B%22from%22:%221727247918466%22,%22to%22:%221727252840266%22%7D%7D%7D&schemaVersion=1&orgId=1

Anything else?

No response

chyezh commented 1 month ago

following log is full message of these test.

2024-09-25 15:36:55.925 [2024/09/25 07:36:55.925 +00:00] [INFO] [flusherimpl/flusher_impl.go:100] ["flusher register vchannel done"] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:36:55.947 [2024/09/25 07:36:55.947 +00:00] [INFO] [querynodev2/services.go:384] ["received load partitions request"] [traceID=0e0a4db9223d7343fc33021ef6af8506] [collectionID=452787834070627086] [partitionIDs="[452787834070627087]"]
2024-09-25 15:36:55.947 [2024/09/25 07:36:55.947 +00:00] [INFO] [querynodev2/services.go:396] ["load partitions done"] [traceID=0e0a4db9223d7343fc33021ef6af8506] [collectionID=452787834070627086] [partitionIDs="[452787834070627087]"]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [querynodev2/services.go:202] ["received watch channel request"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3] [version=1727249816398698604]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [segments/collection.go:95] ["put new collection"] [collectionID=452787834070627086] [schema="name:\"test_collection_2024_09_25_07_36_54_815601RRyqiJvH\" fields:{fieldID:100 name:\"id\" is_primary_key:true data_type:Int64} fields:{fieldID:101 name:\"vector\" data_type:FloatVector type_params:{key:\"dim\" value:\"128\"}} fields:{fieldID:102 name:\"$meta\" description:\"dynamic schema\" data_type:JSON is_dynamic:true} fields:{name:\"RowID\" description:\"row id\" data_type:Int64} fields:{fieldID:1 name:\"Timestamp\" description:\"time stamp\" data_type:Int64} enable_dynamic_field:true"]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [DEBUG] [segments/collection.go:209] ["collection ref increment"] [collectionID=452787834070627086] [refCount=1]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [delegator/delegator.go:861] ["Init delete cache with list delete buffer"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [replicaID=452787884364136990] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [version=1727249816398698604] [startTs=452788175697870854] [sizePerBlock=1048576] [startTime=2024/09/25 07:36:55.742 +00:00]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [delegator/delegator.go:891] ["finish build new shardDelegator"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [replicaID=452787884364136990] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [version=1727249816398698604] [startTs=452788175697870854]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [tsafe/manager.go:69] ["add tSafe done"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [timestamp=2024/09/25 07:36:55.742 +00:00]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [pipeline/manager.go:66] ["start create pipeine"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [delegator/delegator_data.go:344] ["loading growing segments..."] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [segmentIDs="[]"]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [segments/segment_loader.go:206] ["no segment to load"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [segmentType=Growing]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [delegator/delegator_data.go:376] ["load growing segments done"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [segmentIDs="[]"]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [delegator/delegator_data.go:333] ["add growing segments to delegator"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [segmentIDs="[]"]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [pipeline/stream_pipeline.go:81] ["stream pipeline seeks from position with scanner"] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [startFromMessageID=15/1288/0] [timestamp=452788175697870854]
2024-09-25 15:36:56.400 [2024/09/25 07:36:56.399 +00:00] [INFO] [querynodev2/services.go:339] ["watch dml channel success"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3]
2024-09-25 15:36:56.602 [2024/09/25 07:36:56.602 +00:00] [INFO] [querynodev2/services.go:1307] ["sync action"] [traceID=85bf0581634387ff4bff93314c3f3981] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3] [Action=UpdateVersion] [TargetVersion=1727249815948300008]
2024-09-25 15:36:57.029 [2024/09/25 07:36:56.976 +00:00] [INFO] [flusherimpl/channel_lifetime.go:82] ["start to build pipeline"] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:36:57.029 [2024/09/25 07:36:56.977 +00:00] [INFO] [pipeline/flow_graph_dd_node.go:348] ["ddNode add sealed and growing segments"] [collectionID=452787834070627086] ["No. sealed segments"=0] ["No. growing segments"=0]
2024-09-25 15:36:57.029 [2024/09/25 07:36:56.977 +00:00] [INFO] [pipeline/data_sync_service.go:85] ["dataSyncService starting flow graph"] [collectionID=452787834070627086] [vChanName=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:36:57.029 [2024/09/25 07:36:56.977 +00:00] [INFO] [flusherimpl/channel_lifetime.go:128] ["build pipeline done"] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:36:57.029 [2024/09/25 07:36:56.980 +00:00] [DEBUG] [writebuffer/write_buffer.go:285] ["checkpoint from latest consumed msg"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [cpTimestamp=452788175737200450]
2024-09-25 15:37:02.126 [2024/09/25 07:37:02.126 +00:00] [DEBUG] [pipeline/flow_graph_time_tick_node.go:122] ["UpdateChannelCheckpoint success"] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [cpTs=452788175737200450] [cpTime=2024/09/25 07:36:55.892 +00:00]
2024-09-25 15:37:02.597 [2024/09/25 07:37:02.597 +00:00] [INFO] [manager/partition_manager.go:229] ["generate new growing segment"] [pchannel="{\"Name\":\"by-dev-rootcoord-dml_15\",\"Term\":2}"] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0] [collectionID=452787834070627086] [partitionID=452787834070627087] [segmentID=452787834070422316] [limitationPolicy=jitter_segment_limitation] [segmentBinarySize=1029330293] [extraInfo="{\"Jitter\":0.1,\"JitterRatio\":0.9586385392403669,\"MaxSegmentSize\":1073741824}"]
2024-09-25 15:37:02.738 [2024/09/25 07:37:02.738 +00:00] [DEBUG] [pipeline/flow_graph_dd_node.go:205] ["DDNode receive insert messages"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [numRows=1000] [startPosTs=452788177467357854] [endPosTs=452788177467357854]
2024-09-25 15:37:02.738 [2024/09/25 07:37:02.738 +00:00] [INFO] [writebuffer/write_buffer.go:537] ["add growing segment"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:02.740 [2024/09/25 07:37:02.740 +00:00] [DEBUG] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=452787834070627086] [segmentID=452787834070422316] [insertRowNum=1000] [timestampMin=452788177467357854] [timestampMax=452788177467357854]
2024-09-25 15:37:02.740 [2024/09/25 07:37:02.740 +00:00] [INFO] [segments/segment.go:307] ["create segment"] [collectionID=452787834070627086] [partitionID=452787834070627087] [segmentID=452787834070422316] [segmentType=Growing] [level=L1]
2024-09-25 15:37:02.744 [2024/09/25 07:37:02.744 +00:00] [INFO] [delegator/delegator_data.go:333] ["add growing segments to delegator"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [segmentIDs="[452787834070422316]"]
2024-09-25 15:37:02.744 [2024/09/25 07:37:02.744 +00:00] [DEBUG] [delegator/delegator_data.go:164] ["insert into growing segment"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [collectionID=452787834070627086] [segmentID=452787834070422316] [rowCount=1000] [maxTimestamp=452788177467357854]
2024-09-25 15:37:04.404 [2024/09/25 07:37:04.403 +00:00] [DEBUG] [pipeline/flow_graph_dd_node.go:205] ["DDNode receive insert messages"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [numRows=1000] [startPosTs=452788177886788250] [endPosTs=452788177886788250]
2024-09-25 15:37:04.407 [2024/09/25 07:37:04.407 +00:00] [DEBUG] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=452787834070627086] [segmentID=452787834070422316] [insertRowNum=1000] [timestampMin=452788177886788250] [timestampMax=452788177886788250]
2024-09-25 15:37:04.413 [2024/09/25 07:37:04.412 +00:00] [DEBUG] [delegator/delegator_data.go:164] ["insert into growing segment"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [collectionID=452787834070627086] [segmentID=452787834070422316] [rowCount=1000] [maxTimestamp=452788177886788250]
2024-09-25 15:37:04.442 [2024/09/25 07:37:04.442 +00:00] [INFO] [querynodev2/services.go:1307] ["sync action"] [traceID=9d29f08d70e7f8d901d311f5c883eb8d] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3] [Action=UpdateVersion] [TargetVersion=1727249816603237780]
2024-09-25 15:37:06.446 [2024/09/25 07:37:06.446 +00:00] [DEBUG] [pipeline/flow_graph_dd_node.go:205] ["DDNode receive insert messages"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [numRows=1000] [startPosTs=452788178411338397] [endPosTs=452788178411338397]
2024-09-25 15:37:06.448 [2024/09/25 07:37:06.448 +00:00] [DEBUG] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=452787834070627086] [segmentID=452787834070422316] [insertRowNum=1000] [timestampMin=452788178411338397] [timestampMax=452788178411338397]
2024-09-25 15:37:06.453 [2024/09/25 07:37:06.453 +00:00] [DEBUG] [delegator/delegator_data.go:164] ["insert into growing segment"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [collectionID=452787834070627086] [segmentID=452787834070422316] [rowCount=1000] [maxTimestamp=452788178411338397]
2024-09-25 15:37:07.291 [2024/09/25 07:37:07.291 +00:00] [DEBUG] [querynodev2/services.go:733] ["Received SearchRequest"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [channels="[by-dev-rootcoord-dml_15_452787834070627086v0]"] [nq=1] [segmentIDs="[]"] [guaranteeTimestamp=452788178712526849] [mvccTimestamp=0]
2024-09-25 15:37:07.291 [2024/09/25 07:37:07.291 +00:00] [DEBUG] [querynodev2/handlers.go:363] ["start to search channel"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msgID=452788178712526849] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [scope=All] [nq=1] [segmentIDs="[]"]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.327 +00:00] [DEBUG] [delegator/delegator.go:240] ["search segments..."] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [sealedNum=0] [growingNum=1]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [querynodev2/services.go:673] ["start to search segments on worker"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msgID=452788178712526849] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [scope=Streaming] [segmentIDs="[452787834070422316]"]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [querynodev2/services.go:680] ["search segments..."] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msgID=452788178712526849] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [scope=Streaming]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [segments/validate.go:50] ["read target partitions"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [partitionIDs="[452787834070627087]"]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [segments/segment.go:500] ["search segment..."] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [segmentID=452787834070422316] [segmentType=Growing] [withIndex=false]
2024-09-25 15:37:07.331 [2024/09/25 07:37:07.331 +00:00] [DEBUG] [segments/segment.go:524] ["search segment done"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [segmentID=452787834070422316] [segmentType=Growing] [withIndex=false]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [querynodev2/services.go:710] [tr/searchSegments] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msg="search segments done, channel = by-dev-rootcoord-dml_15_452787834070627086v0, segmentIDs = [452787834070422316]"] [duration=4.471285ms]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [delegator/delegator.go:263] ["Delegator search done"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [querynodev2/handlers.go:386] [tr/searchDelegator] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msg="start reduce query result, traceID = d7fb3a26f66a30ae4f613e5cf5729ee4,  vChannel = by-dev-rootcoord-dml_15_452787834070627086v0, segmentIDs = []"] [duration=41.412584ms]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [querynodev2/handlers.go:400] [tr/searchDelegator] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msg="do search with channel done , vChannel = by-dev-rootcoord-dml_15_452787834070627086v0, segmentIDs = []"] [duration=41.433337ms]
2024-09-25 15:37:08.710 [2024/09/25 07:37:08.710 +00:00] [INFO] [querynodev2/services.go:515] ["received release partitions request"] [traceID=e08644bc20972591b58a40666a3a9195] [collection=452787834070627086] [partitions="[452787834070627087]"]
2024-09-25 15:37:08.710 [2024/09/25 07:37:08.710 +00:00] [INFO] [segments/collection.go:199] ["remove partition"] [collection=452787834070627086] [partition=452787834070627087]
2024-09-25 15:37:08.710 [2024/09/25 07:37:08.710 +00:00] [INFO] [querynodev2/services.go:530] ["release partitions done"] [traceID=e08644bc20972591b58a40666a3a9195] [collection=452787834070627086] [partitions="[452787834070627087]"]
2024-09-25 15:37:08.908 [2024/09/25 07:37:08.908 +00:00] [INFO] [querynodev2/services.go:351] ["received unsubscribe channel request"] [traceID=19e84cf104b67a9a31aab320f284150f] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3]
2024-09-25 15:37:08.908 [2024/09/25 07:37:08.908 +00:00] [INFO] [delegator/delegator.go:766] ["updateTSafe quit"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990]
2024-09-25 15:37:08.911 [2024/09/25 07:37:08.911 +00:00] [INFO] [segments/segment.go:1410] ["delete segment from memory"] [traceID=19e84cf104b67a9a31aab320f284150f] [collectionID=452787834070627086] [partitionID=452787834070627087] [segmentID=452787834070422316] [segmentType=Growing] [insertCount=3000]
2024-09-25 15:37:08.913 [2024/09/25 07:37:08.913 +00:00] [INFO] [tsafe/manager.go:107] ["remove tSafe replica"] [traceID=19e84cf104b67a9a31aab320f284150f] [vChannel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:08.913 [2024/09/25 07:37:08.913 +00:00] [DEBUG] [segments/collection.go:218] ["collection ref decrement"] [collectionID=452787834070627086] [refCount=0]
2024-09-25 15:37:08.913 [2024/09/25 07:37:08.913 +00:00] [INFO] [segments/collection.go:119] ["release collection due to ref count to 0"] [collectionID=452787834070627086]
2024-09-25 15:37:08.915 [2024/09/25 07:37:08.915 +00:00] [INFO] [querynodev2/services.go:373] ["unsubscribed channel"] [traceID=19e84cf104b67a9a31aab320f284150f] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3]
2024-09-25 15:37:09.118 [2024/09/25 07:37:09.118 +00:00] [INFO] [manager/seal_queue.go:190] ["send flush message into wal"] [pchannel="{\"Name\":\"by-dev-rootcoord-dml_15\",\"Term\":2}"] [collectionID=452787834070627086] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0] [segmentIDs="[452787834070422316]"] [msgID="{\"MessageID\":{\"MessageID\":{}},\"TimeTick\":452788179145079454,\"TxnCtx\":null,\"Extra\":null}"]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [INFO] [pipeline/data_sync_service.go:113] ["dataSyncService closing flowgraph"] [collectionID=452787834070627086] [vChanName=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [DEBUG] [flowgraph/node.go:196] ["flow graph node closed"] [nodeName=dmInputNode-data-by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [DEBUG] [flowgraph/node.go:196] ["flow graph node closed"] [nodeName=ddNode-by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [DEBUG] [flowgraph/node.go:196] ["flow graph node closed"] [nodeName=writeNode-by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [DEBUG] [flowgraph/node.go:196] ["flow graph node closed"] [nodeName=ttNode-by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [INFO] [flowgraph/input_node.go:93] ["input node message stream closed"] [node=dmInputNode-data-by-dev-rootcoord-dml_15_452787834070627086v0] [collection=452787834070627086] [closeGracefully=false]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [WARN] [pipeline/flow_graph_dd_node.go:119] ["MsgStream closed"] ["ddNode node"=ddNode-by-dev-rootcoord-dml_15_452787834070627086v0] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [collection=452787834070627086]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [INFO] [pipeline/data_sync_service.go:118] ["dataSyncService flowgraph closed"] [collectionID=452787834070627086] [vChanName=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [INFO] [pipeline/data_sync_service.go:127] ["dataSyncService closed"] [collectionID=452787834070627086] [vChanName=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:09.119 [2024/09/25 07:37:09.119 +00:00] [INFO] [flusherimpl/channel_lifetime.go:147] ["flusher unregister vchannel done"] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0]
chyezh commented 1 month ago

/assign

chyezh commented 1 month ago

found that the insert message is fully inserted into growing segment before search.

2024-09-25 15:36:55.742 +0800 CST // subscribe vchannel at querynode
2024-09-25 15:37:02.492 +0800 CST // insert at querynode
2024-09-25 15:37:04.092 +0800 CST // insert at querynode
2024-09-25 15:37:06.093 +0800 CST // insert at querynode
2024-09-25 15:37:07.242 +0800 CST // query gtime at querynode
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [tsafe/manager.go:69] ["add tSafe done"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [timestamp=2024/09/25 07:36:55.742 +00:00]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [delegator/delegator_data.go:344] ["loading growing segments..."] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [segmentIDs="[]"]
2024-09-25 15:36:56.399 [2024/09/25 07:36:56.399 +00:00] [INFO] [pipeline/stream_pipeline.go:81] ["stream pipeline seeks from position with scanner"] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [startFromMessageID=15/1288/0] [timestamp=452788175697870854]
2024-09-25 15:36:56.400 [2024/09/25 07:36:56.399 +00:00] [INFO] [querynodev2/services.go:339] ["watch dml channel success"] [traceID=d4de36e34d5e6a685e1f984b9e2e5e84] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3]
2024-09-25 15:36:56.602 [2024/09/25 07:36:56.602 +00:00] [INFO] [querynodev2/services.go:1307] ["sync action"] [traceID=85bf0581634387ff4bff93314c3f3981] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3] [Action=UpdateVersion] [TargetVersion=1727249815948300008]
2024-09-25 15:37:02.597 [2024/09/25 07:37:02.597 +00:00] [INFO] [manager/partition_manager.go:229] ["generate new growing segment"] [pchannel="{\"Name\":\"by-dev-rootcoord-dml_15\",\"Term\":2}"] [vchannel=by-dev-rootcoord-dml_15_452787834070627086v0] [collectionID=452787834070627086] [partitionID=452787834070627087] [segmentID=452787834070422316] [limitationPolicy=jitter_segment_limitation] [segmentBinarySize=1029330293] [extraInfo="{\"Jitter\":0.1,\"JitterRatio\":0.9586385392403669,\"MaxSegmentSize\":1073741824}"]
2024-09-25 15:37:02.738 [2024/09/25 07:37:02.738 +00:00] [INFO] [writebuffer/write_buffer.go:537] ["add growing segment"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0]
2024-09-25 15:37:02.740 [2024/09/25 07:37:02.740 +00:00] [DEBUG] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=452787834070627086] [segmentID=452787834070422316] [insertRowNum=1000] [timestampMin=452788177467357854] [timestampMax=452788177467357854]
2024-09-25 15:37:02.740 [2024/09/25 07:37:02.740 +00:00] [INFO] [segments/segment.go:307] ["create segment"] [collectionID=452787834070627086] [partitionID=452787834070627087] [segmentID=452787834070422316] [segmentType=Growing] [level=L1]
2024-09-25 15:37:02.744 [2024/09/25 07:37:02.744 +00:00] [INFO] [delegator/delegator_data.go:333] ["add growing segments to delegator"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [segmentIDs="[452787834070422316]"]
2024-09-25 15:37:02.744 [2024/09/25 07:37:02.744 +00:00] [DEBUG] [delegator/delegator_data.go:164] ["insert into growing segment"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [collectionID=452787834070627086] [segmentID=452787834070422316] [rowCount=1000] [maxTimestamp=452788177467357854]
2024-09-25 15:37:04.404 [2024/09/25 07:37:04.403 +00:00] [DEBUG] [pipeline/flow_graph_dd_node.go:205] ["DDNode receive insert messages"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [numRows=1000] [startPosTs=452788177886788250] [endPosTs=452788177886788250]
2024-09-25 15:37:04.407 [2024/09/25 07:37:04.407 +00:00] [DEBUG] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=452787834070627086] [segmentID=452787834070422316] [insertRowNum=1000] [timestampMin=452788177886788250] [timestampMax=452788177886788250]
2024-09-25 15:37:04.413 [2024/09/25 07:37:04.412 +00:00] [DEBUG] [delegator/delegator_data.go:164] ["insert into growing segment"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [collectionID=452787834070627086] [segmentID=452787834070422316] [rowCount=1000] [maxTimestamp=452788177886788250]
2024-09-25 15:37:04.442 [2024/09/25 07:37:04.442 +00:00] [INFO] [querynodev2/services.go:1307] ["sync action"] [traceID=9d29f08d70e7f8d901d311f5c883eb8d] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [currentNodeID=3] [Action=UpdateVersion] [TargetVersion=1727249816603237780]
2024-09-25 15:37:06.446 [2024/09/25 07:37:06.446 +00:00] [DEBUG] [pipeline/flow_graph_dd_node.go:205] ["DDNode receive insert messages"] [segmentID=452787834070422316] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [numRows=1000] [startPosTs=452788178411338397] [endPosTs=452788178411338397]
2024-09-25 15:37:06.448 [2024/09/25 07:37:06.448 +00:00] [DEBUG] [pipeline/insert_node.go:80] ["pipeline fetch insert msg"] [collectionID=452787834070627086] [segmentID=452787834070422316] [insertRowNum=1000] [timestampMin=452788178411338397] [timestampMax=452788178411338397]
2024-09-25 15:37:06.453 [2024/09/25 07:37:06.453 +00:00] [DEBUG] [delegator/delegator_data.go:164] ["insert into growing segment"] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [collectionID=452787834070627086] [segmentID=452787834070422316] [rowCount=1000] [maxTimestamp=452788178411338397]
2024-09-25 15:37:07.291 [2024/09/25 07:37:07.291 +00:00] [DEBUG] [querynodev2/services.go:733] ["Received SearchRequest"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [channels="[by-dev-rootcoord-dml_15_452787834070627086v0]"] [nq=1] [segmentIDs="[]"] [guaranteeTimestamp=452788178712526849] [mvccTimestamp=0]
2024-09-25 15:37:07.291 [2024/09/25 07:37:07.291 +00:00] [DEBUG] [querynodev2/handlers.go:363] ["start to search channel"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msgID=452788178712526849] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [scope=All] [nq=1] [segmentIDs="[]"]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.327 +00:00] [DEBUG] [delegator/delegator.go:240] ["search segments..."] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990] [sealedNum=0] [growingNum=1]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [querynodev2/services.go:673] ["start to search segments on worker"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msgID=452788178712526849] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [scope=Streaming] [segmentIDs="[452787834070422316]"]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [querynodev2/services.go:680] ["search segments..."] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msgID=452788178712526849] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [scope=Streaming]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [segments/validate.go:50] ["read target partitions"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [partitionIDs="[452787834070627087]"]
2024-09-25 15:37:07.328 [2024/09/25 07:37:07.328 +00:00] [DEBUG] [segments/segment.go:500] ["search segment..."] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [segmentID=452787834070422316] [segmentType=Growing] [withIndex=false]
2024-09-25 15:37:07.331 [2024/09/25 07:37:07.331 +00:00] [DEBUG] [segments/segment.go:524] ["search segment done"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [segmentID=452787834070422316] [segmentType=Growing] [withIndex=false]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [querynodev2/services.go:710] [tr/searchSegments] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msg="search segments done, channel = by-dev-rootcoord-dml_15_452787834070627086v0, segmentIDs = [452787834070422316]"] [duration=4.471285ms]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [delegator/delegator.go:263] ["Delegator search done"] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [collectionID=452787834070627086] [channel=by-dev-rootcoord-dml_15_452787834070627086v0] [replicaID=452787884364136990]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [querynodev2/handlers.go:386] [tr/searchDelegator] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msg="start reduce query result, traceID = d7fb3a26f66a30ae4f613e5cf5729ee4,  vChannel = by-dev-rootcoord-dml_15_452787834070627086v0, segmentIDs = []"] [duration=41.412584ms]
2024-09-25 15:37:07.332 [2024/09/25 07:37:07.332 +00:00] [DEBUG] [querynodev2/handlers.go:400] [tr/searchDelegator] [traceID=d7fb3a26f66a30ae4f613e5cf5729ee4] [msg="do search with channel done , vChannel = by-dev-rootcoord-dml_15_452787834070627086v0, segmentIDs = []"] [duration=41.433337ms]
chyezh commented 1 month ago

The test set the radius and range_filter and the vector search's recall is not 100%. Current test case set extra 20% limit to increase the pass ratio, so increase the 20% -> 30%.

        distance_sorted = get_sorted_distance(training_data, [vector_to_search], metric_type)
        r1, r2 = distance_sorted[0][nb//2], distance_sorted[0][nb//2+limit+int((0.2*limit))] # recall is not 100% so add 20% to make sure the range is correct
yanliang567 commented 1 month ago

but this case only fails in streaming node pipeline...

chyezh commented 1 month ago

but this case only fails in streaming node pipeline...

Streaming node didn't change any behaviour of querynode. Just replace the subscription source of shard delegator. The log has confirmed that all inserted message is sent to delegator before the apply of search operation. So I think that it's just a test corner case but not a bug of streaming node.

chyezh commented 1 month ago

reproduced without streaming service at commit cfd636ed5b787a2bf1b50c7930d951e99eebabf1

/home/chyezh/repository/chyezh/milvus/tests/restful_client_v2/testcases/test_vector_operations.py::TestSearchVector::test_search_vector_with_range_search[COSINE] failed: self = <test_vector_operations.TestSearchVector object at 0x7e3236e1f3d0>
metric_type = 'COSINE'

    @pytest.mark.parametrize("metric_type", ["L2", "COSINE", "IP"])
    def test_search_vector_with_range_search(self, metric_type):
        """
        Search a vector with range search with different metric type
        """
        name = gen_collection_name()
        self.name = name
        nb = 3000
        dim = 128
        limit = 100
        schema_payload, data = self.init_collection(name, dim=dim, nb=nb, metric_type=metric_type)
        vector_field = schema_payload.get("vectorField")
        # search data
        vector_to_search = preprocessing.normalize([np.array([random.random() for i in range(dim)])])[0].tolist()
        training_data = [item[vector_field] for item in data]
        distance_sorted = get_sorted_distance(training_data, [vector_to_search], metric_type)
        r1, r2 = distance_sorted[0][nb//2], distance_sorted[0][nb//2+limit+int((0.2*limit))] # recall is not 100% so add 20% to make sure the range is correct
        if metric_type == "L2":
            r1, r2 = r2, r1
        output_fields = get_common_fields_by_data(data, exclude_fields=[vector_field])
        payload = {
            "collectionName": name,
            "data": [vector_to_search],
            "outputFields": output_fields,
            "limit": limit,
            "offset": 0,
            "searchParams": {
                "params": {
                    "radius": r1,
                    "range_filter": r2,
                }
            }
        }
        rsp = self.vector_client.vector_search(payload)
        assert rsp['code'] == 0
        res = rsp['data']
        logger.info(f"res: {len(res)}")
        logger.info(f"r1: {r1}, r2: ")
>       assert len(res) == limit
E       AssertionError: assert 99 == 100
E        +  where 99 = len([{'address': '6894 Alyssa Loop Apt. 287\nNew Rachelfurt, AL 73367', 'distance': 0.76073813, 'email': 'benjaminholland@...Lake Samantha, AS 97746', 'distance': 0.7605656, 'email': 'alyssacochran@example.net', 'id': 17273215443519, ...}, ...])

testcases/test_vector_operations.py:1606: AssertionError
chyezh commented 1 month ago

It seems that get_sorted_distance didn't work correctly.

def get_sorted_distance(train_emb, test_emb, metric_type):
    milvus_sklearn_metric_map = {
        "L2": l2_distance,
        "COSINE": cosine_distance,
        "IP": ip_distance
    }
    distance = pairwise_distances(train_emb, Y=test_emb, metric=milvus_sklearn_metric_map[metric_type], n_jobs=-1)
    distance = np.array(distance.T, order='C', dtype=np.float16)
    distance_sorted = np.sort(distance, axis=1).tolist()
    return distance_sorted

it outputs many same distances. When I use the dtype=np.float32, the output changes much.

np.float16 np.float32
0.719238281 0.719054639
0.719238281 0.719127595
0.719238281 0.719179928
0.719238281 0.719190657
0.719238281 0.719231904
0.719238281 0.719250858
0.719238281 0.719253421
0.719238281 0.719267368
0.719238281 0.719320059
0.719726563 0.719569087
0.719726563 0.719574213
0.719726563 0.7196064
0.719726563 0.719633102
0.719726563 0.719652593
0.719726563 0.719673634
0.719726563 0.719692171
0.719726563 0.719773591
0.719726563 0.719815731
0.719726563 0.719831347
0.719726563 0.719866216
0.720214844 0.719989359
0.720214844 0.720114648
0.720214844 0.720292628
0.720703125 0.720496118
0.720703125 0.720554113
0.720703125 0.720606089
0.720703125 0.720620632
0.720703125 0.720653832

@zhuwenxing need help.

zhuwenxing commented 1 month ago

good catch! When calculating the distance of float_vector in Milvus, float32 is used, so it should also be changed to float32 here to ensure that the calculated results are consistent with those of Milvus.

chyezh commented 1 month ago

Should be fixed by #36542.