milvus icon indicating copy to clipboard operation
milvus copied to clipboard

Published 20 hours ago • verified publisher icon milvus-io

[Bug]: Query performance is very low (below 150qps) despite important query node number

Open ThomasAlxDmy opened this issue 2 years ago • 15 comments

Is there an existing issue for this?

  • [X] I have searched the existing issues

Environment

- Milvus version: 2.2.2
- Deployment mode(standalone or cluster): cluster AWS 
- MQ type(rocksmq, pulsar or kafka):  pulsar  
- SDK version(e.g. pymilvus v2.0.0rc2): github.com/milvus-io/milvus-sdk-go/v2 v2.2.0
- OS(Ubuntu or CentOS): CentOS
- CPU/Memory: c5.4xlarge => 16 VCPU, 32GB
- GPU: 
- Others:

Current Behavior

Querying on a new sending node (other AWS server) and doing some random benchmark I see very low throughput.

I'm doing 2 machine (1 local + 1 aws server) 4 processes, batches of 1000query with 10 go-routines. Each go routines as a single connection to a single Proxy node (using 2 proxy nodes randomly).

Here's my collection info:

  • name: embedding
  • FloatVector: 384
  • _default_idx: IVF_FLAT
  • metric_type: IP nlist:1800
  • Approx Entity Count :11,032,326
  • Collection is loaded and replicated on 30 query nodes.
  • Collection gains about 3k-4k vectors/second (through another process inserting new records)

Collection ID: 438693529927026545 Collection Name: mycollection Partitions: Fields:

  • Field ID: 0 Field Name: RowID Field Type: Int64
  • Field ID: 1 Field Name: Timestamp Field Type: Int64
  • Field ID: 100 Field Name: entity_id Field Type: Int64 - Primary Key, AutoID: false
  • Field ID: 101 Field Name: text_count Field Type: Int16
  • Field ID: 102 Field Name: hash_count Field Type: Int8
  • Field ID: 103 Field Name: other_count Field Type: Int8
  • Field ID: 104 Field Name: mention_count Field Type: Int8
  • Field ID: 105 Field Name: media_count Field Type: Int8
  • Field ID: 106 Field Name: is_bool Field Type: Bool
  • Field ID: 107 Field Name: has_quote Field Type: Bool
  • Field ID: 108 Field Name: creation_timestamp Field Type: Int32
  • Field ID: 109 Field Name: embedding Field Type: FloatVector - Type Param dim: 384 Consistency Level: Bounded Start position for channel by-dev-rootcoord-dml_32: [8 42 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_35: [8 45 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_56: [8 66 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_30: [8 40 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_47: [8 57 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_48: [8 58 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_51: [8 61 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_52: [8 62 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_34: [8 44 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_38: [8 48 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_42: [8 52 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_43: [8 53 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_44: [8 54 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_55: [8 65 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_37: [8 47 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_46: [8 56 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_50: [8 60 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_53: [8 63 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_54: [8 64 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_41: [8 51 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_40: [8 50 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_45: [8 55 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_49: [8 59 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_59: [8 69 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_36: [8 46 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_39: [8 49 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_57: [8 67 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_31: [8 41 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_58: [8 68 16 0 24 0 32 0] Start position for channel by-dev-rootcoord-dml_33: [8 43 16 0 24 0 32 0]

here's the query:

        vec2search := []entity.Vector{searchParams.vector}
	start := time.Now()

	sp, _ := entity.NewIndexIvfFlatSearchParam(1)
	sRet, err := milvusClient.Search(ctx, "mycollection", nil, "", []string{"entity_id"},
		vec2search, "embedding", entity.IP, 20, sp,
		client.WithSearchQueryConsistencyLevel(entity.ClBounded), client.WithLimit(20))
	if err != nil {
		fmt.Println(err)
		return false, 0, 0, fmt.Errorf("failed to search collection, err: %v", err)
	}
image

Process 1:

Queried nbSearch: 1000, nbError: 0 records in 29.460374951s (total:4m53.267963685s) => 33.94 qps (avg latency: 293.27ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.839000831s (total:4m55.789648876s) => 33.51 qps (avg latency: 295.79ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 30.076635863s (total:4m59.234612841s) => 33.25 qps (avg latency: 299.23ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.815182548s (total:4m56.846613236s) => 33.54 qps (avg latency: 296.85ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 30.022772186s (total:4m58.777589485s) => 33.31 qps (avg latency: 298.78ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.117218885s (total:4m49.991001462s) => 34.34 qps (avg latency: 289.99ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 27.628981886s (total:4m34.572110472s) => 36.20 qps (avg latency: 274.57ms, avg results: 20.00)

Process 2

Queried nbSearch: 1000, nbError: 0 records in 27.778894894s (total:4m36.510751041s) => 36.00 qps (avg latency: 276.51ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 27.79649825s (total:4m36.765207525s) => 35.98 qps (avg latency: 276.76ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 27.916158123s (total:4m38.357692297s) => 35.82 qps (avg latency: 278.36ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 27.888368544s (total:4m37.913993133s) => 35.86 qps (avg latency: 277.91ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 28.066101082s (total:4m39.291657502s) => 35.63 qps (avg latency: 279.29ms, avg results: 20.00)

Process 3

Queried nbSearch: 1000, nbError: 0 records in 29.68494171s (total:4m55.683594435s) => 33.69 qps (avg latency: 295.68ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.485262268s (total:4m53.881224462s) => 33.92 qps (avg latency: 293.88ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 28.993143544s (total:4m48.817353677s) => 34.49 qps (avg latency: 288.82ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.305538861s (total:4m51.002148977s) => 34.12 qps (avg latency: 291.00ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.322604115s (total:4m50.888327916s) => 34.10 qps (avg latency: 290.89ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 29.495849313s (total:4m53.244181178s) => 33.90 qps (avg latency: 293.24ms, avg results: 20.00)

Process 4

Queried nbSearch: 1000, nbError: 0 records in 1m14.986758708s (total:6m13.327321304s) => 13.34 qps (avg latency: 373.33ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 1m17.293226959s (total:6m24.871092199s) => 12.94 qps (avg latency: 384.87ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 1m16.322780041s (total:6m19.836449932s) => 13.10 qps (avg latency: 379.84ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 1m16.321409708s (total:6m19.74849057s) => 13.10 qps (avg latency: 379.75ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records in 1m17.547682833s (total:6m25.682184784s) => 12.90 qps (avg latency: 385.68ms, avg results: 20.00)

Expected Behavior

No response

Steps To Reproduce

No response

Milvus Log

No response

Anything else?

No response

ThomasAlxDmy avatar Jan 12 '23 03:01 ThomasAlxDmy

I looked into QueryCoord/Query node no logs stands out that would point to a problem. I'm sure what I'm doing wrong here, would love some help!

ThomasAlxDmy avatar Jan 12 '23 03:01 ThomasAlxDmy

I looked into QueryCoord/Query node no logs stands out that would point to a problem. I'm sure what I'm doing wrong here, would love some help!

Question, if you already know the entity_id and embedding it self, why do you do search?

xiaofan-luan avatar Jan 12 '23 06:01 xiaofan-luan

I actually don't know the entity_id, I'm trying to get back an entity id given a vector in my embedding column (search the associated entity_id with this vector). Is this not what this do?

milvusClient.Search(ctx, "mycollection", nil, "", []string{"entity_id"}, vec2search, "embedding", entity.IP, 20, sp,
		client.WithSearchQueryConsistencyLevel(entity.ClBounded), client.WithLimit(20))

ThomasAlxDmy avatar Jan 12 '23 07:01 ThomasAlxDmy

  • :

Gotcha, 30 * 16 vcpu with 10m data should be much faster than hundred QPS. Few things to check:

  1. If all the querynodes in the cluster are balanced? I mean the CPU usage.
  2. If balanced
    1. if you are using too large nprobes? try to change nprobe to 16-32 and retry
    2. If Cpu usage high enough -> change to HNSW index and retyr
    3. If not -> check prometheus metrics and logs, see if it's because timetick delay and search can not be issued due to consistency limited.
  3. if not balanced
    1. if there are only shard numbers querynode with very high cpu usage, might be related to growing data, use more shards or smaller growing segment ratio would help. (dataCoord.segment.sealProportion)
    2. otherwise you will need to check the balance policy, why there are some querynode with less load

xiaofan-luan avatar Jan 12 '23 08:01 xiaofan-luan

  1. Yes node are well balanced CPU wise.
  2. as you can see in my query sp, _ := entity.NewIndexIvfFlatSearchParam(1) I also tried with 20 & 32 - makes no difference.

here's what I see on the query node during a query:

[2023/01/12 18:19:19.103 +00:00] [DEBUG] [querynode/impl.go:724] ["Received SearchRequest"] [traceID=431d4bef9128619a] [vChannels="[by-dev-rootcoord-dml_37_438693529927026545v7,by-dev-rootcoord-dml_40_438693529927026545v10]"] [segmentIDs="[]"] [guaranteeTimestamp=438710450014650372] [timeTravel=18446744073709551615]
[2023/01/12 18:19:19.103 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529942273577] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.104 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=431d4bef9128619a] [vChannel=by-dev-rootcoord-dml_37_438693529927026545v7] [segmentIDs="[]"]
[2023/01/12 18:19:19.104 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=0] [partitionIDs="[]"]
[2023/01/12 18:19:19.104 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(431d4bef9128619a)] [msg="enqueue done"] [duration=33.088µs]
[2023/01/12 18:19:19.105 +00:00] [DEBUG] [querynode/task_read.go:173] ["query msg can do"] [collectionID=438693529927026545] [sm.GuaranteeTimestamp=2023/01/12 18:19:14.072 +00:00] [serviceTime=2023/01/12 18:19:18.622 +00:00] ["delta milliseconds"=-4550] [channel=by-dev-rootcoord-dml_37_438693529927026545v7] [msgID=438710451325370372]
[2023/01/12 18:19:19.105 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529939670033] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.105 +00:00] [DEBUG] [querynode/task_read.go:180] [tr/waitTSafeTimeRecorder] [msg="wait for tsafe done"] [duration=22.024µs]
[2023/01/12 18:19:19.105 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529934662297] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.105 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=431d4bef9128619a] [vChannel=by-dev-rootcoord-dml_40_438693529927026545v10] [segmentIDs="[]"]
[2023/01/12 18:19:19.105 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=0] [partitionIDs="[]"]
[2023/01/12 18:19:19.105 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(431d4bef9128619a)] [msg="enqueue done"] [duration=104.974µs]
[2023/01/12 18:19:19.106 +00:00] [DEBUG] [querynode/task_read.go:173] ["query msg can do"] [collectionID=438693529927026545] [sm.GuaranteeTimestamp=2023/01/12 18:19:14.072 +00:00] [serviceTime=2023/01/12 18:19:18.622 +00:00] ["delta milliseconds"=-4550] [channel=by-dev-rootcoord-dml_40_438693529927026545v10] [msgID=438710451325370372]
[2023/01/12 18:19:19.106 +00:00] [DEBUG] [querynode/task_read.go:180] [tr/waitTSafeTimeRecorder] [msg="wait for tsafe done"] [duration=52.144µs]
[2023/01/12 18:19:19.109 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529944677347] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.109 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529932258033] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.113 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529927228394] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.114 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529942273388] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.119 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529944677492] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.123 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529929654236] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.123 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529932258189] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.124 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529937266493] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.130 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529934662647] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.132 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529932258004] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.132 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=8942b1907336b65] [segmentIDs="[438693529939669728,438693529927228416,438693529942273577,438693529944677347,438693529929654539,438693529934662254,438693529932258004,438693529937266058]"]
[2023/01/12 18:19:19.132 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529937266551] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.132 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529939670178] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.134 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529939669756] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.135 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=8942b1907336b65] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_37_438693529927026545v7, segmentIDs = []"] [duration=162.210773ms]
[2023/01/12 18:19:19.135 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=8942b1907336b65] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.135 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=8942b1907336b65] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_37_438693529927026545v7, segmentIDs = []"] [duration=162.316607ms]
[2023/01/12 18:19:19.136 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(5b3d10f134cb77fd)] [msg="start to process"] [duration=67.02202ms]
[2023/01/12 18:19:19.136 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529944677129] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.136 +00:00] [DEBUG] [querynode/validate.go:115] ["read target partitions on stream replica"] [traceID=5b3d10f134cb77fd] [collectionID=438693529927026545] [partitionIDs="[438693529927026546]"]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529934662649] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529929654422] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529944676752] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529927228405] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529932258194] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529942273246] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529937266403] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.137 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529939669757] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.139 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529939670223] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.140 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529929654714] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.140 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=2e56946eefb79f1f] [msgID=438710451299155970] [segmentID=438693529942273810] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.140 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=2e56946eefb79f1f] [segmentIDs="[438693529942273810,438693529929654714,438693529932258033,438693529927228394,438693529934662647,438693529944677289,438693529937266551,438693529939670033]"]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529932258130] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=2e56946eefb79f1f] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_54_438693529927026545v24, segmentIDs = []"] [duration=157.180052ms]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(40171f661264bf69)] [msg="start to process"] [duration=55.340656ms]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=2e56946eefb79f1f] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/validate.go:115] ["read target partitions on stream replica"] [traceID=40171f661264bf69] [collectionID=438693529927026545] [partitionIDs="[438693529927026546]"]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=2e56946eefb79f1f] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_54_438693529927026545v24, segmentIDs = []"] [duration=157.559681ms]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529939670004] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.141 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=2e56946eefb79f1f] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=2e56946eefb79f1f] [msg="search done in all shards"] [duration=158.008352ms]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529927228413] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529929654333] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529927228403] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529937266158] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529929654715] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529944677535] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529934662341] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529932258221] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.142 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529942273913] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.143 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529942273518] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.144 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529937266085] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.145 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529944677202] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.147 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=8942b1907336b65] [msgID=438710451299155969] [segmentID=438693529934662603] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=8942b1907336b65] [segmentIDs="[438693529927228403,438693529929654162,438693529944677115,438693529939670049,438693529932257989,438693529937266493,438693529942273388,438693529934662603]"]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(40171f661264bf69)] [msg="start to process"] [duration=62.192697ms]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529934662501] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/validate.go:115] ["read target partitions on stream replica"] [traceID=40171f661264bf69] [collectionID=438693529927026545] [partitionIDs="[438693529927026546]"]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=8942b1907336b65] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_34_438693529927026545v4, segmentIDs = []"] [duration=175.108159ms]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=8942b1907336b65] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=8942b1907336b65] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_34_438693529927026545v4, segmentIDs = []"] [duration=175.189877ms]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=8942b1907336b65] [numbers=2] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529932257802] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=8942b1907336b65] [msg="search done in all shards"] [duration=175.696861ms]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529942273333] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529929654340] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529939669729] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.149 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529929654339] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529937265955] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529927228415] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529934662051] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.148 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529944676941] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.153 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529942273547] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.158 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529937266406] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.164 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529927228398] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.166 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529937266245] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.167 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=7780a69791e7d9a9] [segmentIDs="[438693529929654339,438693529942273518,438693529927228398,438693529932258130,438693529937266245,438693529944677202,438693529934662501,438693529939670178]"]
[2023/01/12 18:19:19.167 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(40171f661264bf69)] [msg="start to process"] [duration=77.657551ms]
[2023/01/12 18:19:19.167 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=7780a69791e7d9a9] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_35_438693529927026545v5, segmentIDs = []"] [duration=116.915274ms]
[2023/01/12 18:19:19.167 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=7780a69791e7d9a9] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.167 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=7780a69791e7d9a9] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_35_438693529927026545v5, segmentIDs = []"] [duration=117.01358ms]
[2023/01/12 18:19:19.167 +00:00] [DEBUG] [querynode/validate.go:115] ["read target partitions on stream replica"] [traceID=40171f661264bf69] [collectionID=438693529927026545] [partitionIDs="[438693529927026546]"]
[2023/01/12 18:19:19.170 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529939669583] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.170 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529927228401] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.170 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529929654104] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.172 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529934662427] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.173 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529944676883] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.173 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529932257816] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.174 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529927228421] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.174 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529942273143] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.174 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529937266102] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.177 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529942273594] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.183 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529939669757] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.187 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529942273913] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.189 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529929654333] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.192 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529937266403] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.194 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=7780a69791e7d9a9] [msgID=438710451312263172] [segmentID=438693529934662605] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.194 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529942273246] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.194 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=7780a69791e7d9a9] [segmentIDs="[438693529929654715,438693529942273547,438693529927228401,438693529932258189,438693529934662605,438693529937266406,438693529944677129,438693529939670223]"]
[2023/01/12 18:19:19.196 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529937265955] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=7780a69791e7d9a9] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_49_438693529927026545v19, segmentIDs = []"] [duration=146.894074ms]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(431d4bef9128619a)] [msg="start to process"] [duration=92.209216ms]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=7780a69791e7d9a9] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/validate.go:115] ["read target partitions on stream replica"] [traceID=431d4bef9128619a] [collectionID=438693529927026545] [partitionIDs="[438693529927026546]"]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529942273577] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529927228416] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529929654539] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529944677535] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=7780a69791e7d9a9] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_49_438693529927026545v19, segmentIDs = []"] [duration=147.574214ms]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=7780a69791e7d9a9] [numbers=2] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=7780a69791e7d9a9] [msg="search done in all shards"] [duration=147.766256ms]
[2023/01/12 18:19:19.197 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529944677347] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.198 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529934662254] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.198 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529939669728] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.198 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529937266058] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.198 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529932258004] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.201 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=1d5b183b1015a12f] [msgID=438710451312263169] [segmentID=438693529932257847] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.203 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=1d5b183b1015a12f] [segmentIDs="[438693529939669756,438693529942273594,438693529944677492,438693529932257847,438693529927228395,438693529934662297,438693529929654236,438693529937266085]"]
[2023/01/12 18:19:19.203 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(431d4bef9128619a)] [msg="start to process"] [duration=97.804711ms]
[2023/01/12 18:19:19.203 +00:00] [DEBUG] [querynode/validate.go:115] ["read target partitions on stream replica"] [traceID=431d4bef9128619a] [collectionID=438693529927026545] [partitionIDs="[438693529927026546]"]
[2023/01/12 18:19:19.203 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529934662559] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.204 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529944677028] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.204 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529927228399] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.204 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529929654685] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.205 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529932258369] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.206 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529939669840] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.206 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529942273491] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.206 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529937266261] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.208 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529944676941] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.211 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529927228413] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.213 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529927228415] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.215 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529937266158] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.221 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529942273333] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.223 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529939670004] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.225 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529929654422] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.229 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529934662649] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.204 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=1d5b183b1015a12f] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_53_438693529927026545v23, segmentIDs = []"] [duration=160.314339ms]
[2023/01/12 18:19:19.229 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=1d5b183b1015a12f] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.230 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529944677347] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.229 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=1d5b183b1015a12f] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_53_438693529927026545v23, segmentIDs = []"] [duration=185.749807ms]
[2023/01/12 18:19:19.231 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=1d5b183b1015a12f] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.231 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=1d5b183b1015a12f] [msg="search done in all shards"] [duration=187.342214ms]
[2023/01/12 18:19:19.233 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529929654340] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.236 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529944676752] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.237 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529939669729] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.237 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529934662341] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.238 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529927228405] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.239 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529937266102] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.239 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529932258221] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.239 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=40171f661264bf69] [segmentIDs="[438693529939670004,438693529927228413,438693529929654333,438693529937266158,438693529944677535,438693529934662341,438693529932258221,438693529942273913]"]
[2023/01/12 18:19:19.240 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=40171f661264bf69] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_46_438693529927026545v16, segmentIDs = []"] [duration=154.480867ms]
[2023/01/12 18:19:19.240 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=40171f661264bf69] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.240 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=40171f661264bf69] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_46_438693529927026545v16, segmentIDs = []"] [duration=154.577629ms]
[2023/01/12 18:19:19.240 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529942273143] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.243 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529927228399] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.244 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529944676883] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.244 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529934662051] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.245 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529927228421] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.247 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529929654685] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.247 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529934662427] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.247 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529937266261] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.248 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529932257802] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.248 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=40171f661264bf69] [segmentIDs="[438693529934662051,438693529932257802,438693529942273333,438693529929654340,438693529939669729,438693529937265955,438693529927228415,438693529944676941]"]
[2023/01/12 18:19:19.248 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529944677028] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.248 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=40171f661264bf69] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_38_438693529927026545v8, segmentIDs = []"] [duration=162.762245ms]
[2023/01/12 18:19:19.248 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=40171f661264bf69] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.248 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=40171f661264bf69] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_38_438693529927026545v8, segmentIDs = []"] [duration=162.854185ms]
[2023/01/12 18:19:19.248 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529942273577] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.249 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529942273491] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.252 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529932258004] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.254 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=5b3d10f134cb77fd] [msgID=438710451312263173] [segmentID=438693529932258194] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.254 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=5b3d10f134cb77fd] [segmentIDs="[438693529934662649,438693529929654422,438693529944676752,438693529927228405,438693529942273246,438693529932258194,438693529937266403,438693529939669757]"]
[2023/01/12 18:19:19.254 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=5b3d10f134cb77fd] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_55_438693529927026545v25, segmentIDs = []"] [duration=186.050473ms]
[2023/01/12 18:19:19.254 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=5b3d10f134cb77fd] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.254 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=5b3d10f134cb77fd] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_55_438693529927026545v25, segmentIDs = []"] [duration=186.137393ms]
[2023/01/12 18:19:19.255 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=5b3d10f134cb77fd] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.255 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=5b3d10f134cb77fd] [msg="search done in all shards"] [duration=186.356188ms]
[2023/01/12 18:19:19.255 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529939669728] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.255 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529932258369] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.256 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529939669840] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.258 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529929654104] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.260 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529939669583] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.261 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529937266058] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.262 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=40171f661264bf69] [msgID=438710451325370371] [segmentID=438693529932257816] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.262 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=40171f661264bf69] [segmentIDs="[438693529939669583,438693529929654104,438693529934662427,438693529944676883,438693529932257816,438693529927228421,438693529942273143,438693529937266102]"]
[2023/01/12 18:19:19.262 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=40171f661264bf69] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_56_438693529927026545v26, segmentIDs = []"] [duration=176.558838ms]
[2023/01/12 18:19:19.262 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=40171f661264bf69] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.262 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=40171f661264bf69] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_56_438693529927026545v26, segmentIDs = []"] [duration=176.649541ms]
[2023/01/12 18:19:19.262 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=40171f661264bf69] [numbers=3] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.262 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=40171f661264bf69] [msg="search done in all shards"] [duration=177.038322ms]
[2023/01/12 18:19:19.264 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529927228416] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.264 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529929654539] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.264 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529934662254] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.264 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=431d4bef9128619a] [segmentIDs="[438693529942273577,438693529927228416,438693529929654539,438693529944677347,438693529934662254,438693529932258004,438693529937266058,438693529939669728]"]
[2023/01/12 18:19:19.264 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=431d4bef9128619a] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_37_438693529927026545v7, segmentIDs = []"] [duration=160.057002ms]
[2023/01/12 18:19:19.264 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=431d4bef9128619a] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=431d4bef9128619a] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_37_438693529927026545v7, segmentIDs = []"] [duration=160.125463ms]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529934662559] [segmentType=2] [loadIndex=false]
[2023/01/12 18:19:19.265 +00:00] [INFO] [querynode/search.go:97] ["search growing/sealed segments without indexes"] [traceID=431d4bef9128619a] [segmentIDs="[438693529934662559,438693529944677028,438693529927228399,438693529929654685,438693529932258369,438693529939669840,438693529942273491,438693529937266261]"]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=431d4bef9128619a] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_40_438693529927026545v10, segmentIDs = []"] [duration=160.712528ms]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=431d4bef9128619a] [numbers=1] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/impl.go:915] [tr/SearchShard] [traceID=431d4bef9128619a] [msg="do reduce done in shard cluster, vChannel = by-dev-rootcoord-dml_40_438693529927026545v10, segmentIDs = []"] [duration=160.766868ms]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/result.go:86] [reduceSearchResultData] [traceID=431d4bef9128619a] [numbers=2] [targetNq=1] [targetTopk=20]
[2023/01/12 18:19:19.265 +00:00] [DEBUG] [querynode/impl.go:773] [tr/Search] [traceID=431d4bef9128619a] [msg="search done in all shards"] [duration=162.035403ms]
[2023/01/12 18:19:19.319 +00:00] [INFO] [gc/gc_tuner.go:81] ["GC Tune done"] ["previous GOGC"=30] ["heapuse "=71] ["total memory"=29595] ["next GC"=70] ["new GOGC"=30]

ThomasAlxDmy avatar Jan 12 '23 18:01 ThomasAlxDmy

we can see many lines of logs show: [2023/01/12 18:19:19.255 +00:00] [DEBUG] [querynode/segment.go:344] ["do search on segment done"] [traceID=431d4bef9128619a] [msgID=438710451325370372] [segmentID=438693529939669728] [segmentType=2] [loadIndex=false] which indicates the searches are doing without indexes. Please make sure all the index tasks were completed, and then you can release the collection and reload the collection.

yanliang567 avatar Jan 14 '23 10:01 yanliang567

/assign @ThomasAlxDmy please try as suggested above, and feel free to keep us posted.

yanliang567 avatar Jan 14 '23 10:01 yanliang567

Thanks for helping @yanliang567 @xiaofan-luan

So I started to spin up a smaller environment so we can iterate faster and understand what's going on:

image

Collection Loaded => 1,265,800 records. I try creating/recreating the index and reloading the collection same effect, I still see some segment not being indexed.

In this setting I have 4 queries nodes (c6in.8xlarge): 32CPU | 64 GB RAM | 50 Gbps

image

I max at 850qps =>

Queried nbSearch: 1000, nbError: 0 records(1 vectors) in 1.187706286s (total:15m6.458642827s) => 842.46 vps (avg latency: 906.46ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records(1 vectors) in 1.211963839s (total:15m17.097020959s) => 825.76 vps (avg latency: 917.10ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records(1 vectors) in 1.185255229s (total:15m7.283401702s) => 843.88 vps (avg latency: 907.28ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records(1 vectors) in 1.181801638s (total:15m29.827552142s) => 846.74 vps (avg latency: 929.83ms, avg results: 20.00) 
Queried nbSearch: 1000, nbError: 0 records(1 vectors) in 1.186050791s (total:14m25.938503893s) => 843.17 vps (avg latency: 865.94ms, avg results: 20.00)

Index node:

[2023/01/15 06:46:52.555 +00:00] [INFO] [indexcoord/garbage_collector.go:270] ["recycle index files"] [buildID=438763080441655109] ["meta files num"=6] ["chunkManager files num"=6]
[2023/01/15 06:46:52.555 +00:00] [INFO] [indexcoord/garbage_collector.go:283] ["index files recycle success"] [buildID=438763080441655109] ["delete index files num"=0]
[2023/01/15 06:46:54.898 +00:00] [DEBUG] [indexcoord/index_coord.go:772] ["IndexCoord GetIndexInfos"] [collectionID=438763080440024570] [indexName=] [segIDs="[438763080441653218]"]
[2023/01/15 06:46:54.899 +00:00] [INFO] [indexcoord/index_coord.go:829] ["IndexCoord DescribeIndex"] [collectionID=438763080440024570] [indexName=]
[2023/01/15 06:46:54.902 +00:00] [INFO] [indexcoord/index_coord.go:588] ["IndexCoord completeIndexInfo"] [collID=438763080440024570] [indexName=test]
[2023/01/15 06:46:54.902 +00:00] [DEBUG] [indexcoord/meta_table.go:651] ["IndexCoord get index states success"] [indexID=438763080441655077] [total=32] [None=0] [Unissued=0] [InProgress=0] [Finished=32] [Failed=0]

Query node:

[2023/01/15 06:54:30.654 +00:00] [INFO] [querynode/segment_loader.go:826] ["All data has been read, there is no more data"] [collectionID=438763080440024570] [channel=by-dev-rootcoord-dml_83] [msgID="CLkOEJO9ARgAIAA="]
[2023/01/15 06:54:30.654 +00:00] [INFO] [querynode/segment_loader.go:854] ["from dml check point load done"] [subName=querynode-delta-loader-15-438763080440024570-4678754740599929807] [timeTake=175.590902ms]
[2023/01/15 06:54:30.654 +00:00] [INFO] [msgstream/mq_msgstream.go:182] ["start to close mq msg stream"] ["producer num"=0] ["consumer num"=1]
time="2023-01-15T06:54:30Z" level=info msg="The consumer[264] successfully unsubscribed" consumerID=264 name=ahddj subscription=querynode-delta-loader-15-438763080440024570-4678754740599929807 topic="persistent://public/default/by-dev-rootcoord-dml_83"
time="2023-01-15T06:54:30Z" level=info msg="Closing consumer=264" consumerID=264 name=ahddj subscription=querynode-delta-loader-15-438763080440024570-4678754740599929807 topic="persistent://public/default/by-dev-rootcoord-dml_83"
time="2023-01-15T06:54:30Z" level=info msg="[Closed consumer]" consumerID=264 name=ahddj subscription=querynode-delta-loader-15-438763080440024570-4678754740599929807 topic="persistent://public/default/by-dev-rootcoord-dml_83"
[2023/01/15 06:54:30.658 +00:00] [INFO] [querynode/load_segment_task.go:130] ["LoadSegmentTask Execute done"] [collectionID=438763080440024570] [replicaID=438763104202653712] [msgID=2669]
[2023/01/15 06:54:30.658 +00:00] [INFO] [querynode/impl.go:501] ["loadSegmentsTask WaitToFinish done"] [collectionID=438763080440024570] [segmentIDs="[438763080440024583,438763080440229698]"] [nodeID=15]
[2023/01/15 06:54:30.658 +00:00] [INFO] [querynode/shard_cluster.go:281] ["ShardCluster update segment"] [collectionID=438763080440024570] [channel=by-dev-rootcoord-dml_83_438763080440024570v20] [replicaID=438763104202653712] [nodeID=15] [segmentID=438763080440024583] [state=3]
[2023/01/15 06:54:30.658 +00:00] [INFO] [querynode/shard_cluster.go:281] ["ShardCluster update segment"] [collectionID=438763080440024570] [channel=by-dev-rootcoord-dml_83_438763080440024570v20] [replicaID=438763104202653712] [nodeID=15] [segmentID=438763080440229698] [state=3]
[2023/01/15 06:54:30.658 +00:00] [INFO] [querynode/shard_cluster_version.go:91] ["Update shard cluster version"] [newVersionID=2] [newAllocation="{Node 15: [438763080440024583 438763080440229698] }"]
[2023/01/15 06:54:30.658 +00:00] [INFO] [querynode/impl_utils.go:48] ["LoadSegment transfer load done"] [traceID=208cd9180900ff18] [shard=by-dev-rootcoord-dml_83_438763080440024570v20] [segmentIDs="[438763080440024583,438763080440229698]"]
[2023/01/15 06:54:36.588 +00:00] [DEBUG] [querynode/flow_graph_service_time_node.go:70] ["update tSafe:"] [collectionID=438763080440024570] [tSafe=438767629472890881] [tSafe_p=2023/01/15 06:54:36.395 +00:00] [tsLag=193.300787ms] [channel=by-dev-rootcoord-dml_92_438763080440024570v29]

[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(768cc85123de985f)] [msg="enqueue done"] [duration=7.291µs]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:929] ["segments distribution"] [nodeID=15] [segments="[438763080441653034]"]
[2023/01/15 06:56:09.320 +00:00] [DEBUG] [querynode/task_read.go:80] [tr/searchTask(523f606e4fa23962)] [msg="start to process"] [duration=1.809204ms]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(768cc85123de985f)] [msg="enqueue done"] [duration=4.01µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=66d3b50ae876ac1b] [vChannel=by-dev-rootcoord-dml_79_438763080440024570v16] [segmentIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(768cc85123de985f)] [msg="enqueue done"] [duration=15.015µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:173] ["query msg can do"] [collectionID=438763080440024570] [sm.GuaranteeTimestamp=2023/01/15 06:56:04.295 +00:00] [serviceTime=2023/01/15 06:56:08.845 +00:00] ["delta milliseconds"=-4550] [channel=by-dev-rootcoord-delta_91_438763080440024570v28] [msgID=438767653826068514]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(66d3b50ae876ac1b)] [msg="enqueue done"] [duration=441.318µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:724] ["Received SearchRequest"] [traceID=4c6daa0bd718d9b3] [vChannels="[by-dev-rootcoord-dml_91_438763080440024570v28,by-dev-rootcoord-dml_85_438763080440024570v22,by-dev-rootcoord-dml_72_438763080440024570v9]"] [segmentIDs="[]"] [guaranteeTimestamp=438767652515348536] [timeTravel=18446744073709551615]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=66d3b50ae876ac1b] [vChannel=by-dev-rootcoord-dml_68_438763080440024570v5] [segmentIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=1] [partitionIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/validate.go:50] ["read target partitions on historical replica"] [traceID=713d3e5adf43d7aa] [collectionID=438763080440024570] [partitionIDs="[438763080440024571]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:816] ["start do subsearch"] [traceID=66d3b50ae876ac1b] [fromShardLeader=true] [vChannel=by-dev-rootcoord-dml_74_438763080440024570v11] [segmentIDs="[438763080441653265]"]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:929] ["segments distribution"] [nodeID=15] [segments="[438763080441653118]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:816] ["start do subsearch"] [traceID=5037a6c77dfb4690] [fromShardLeader=true] [vChannel=by-dev-rootcoord-dml_71_438763080440024570v8] [segmentIDs="[438763080441652639]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=6fcc0ec2ae51b0d4] [msgID=438767653826068505] [segmentID=438763080441653035] [segmentType=3] [loadIndex=true]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=713d3e5adf43d7aa] [msgID=438767653826068502] [segmentID=438763080440229696] [segmentType=3] [loadIndex=false]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/validate.go:50] ["read target partitions on historical replica"] [traceID=523f606e4fa23962] [collectionID=438763080440024570] [partitionIDs="[438763080440024571]"]
[2023/01/15 06:56:09.320 +00:00] [DEBUG] [querynode/validate.go:50] ["read target partitions on historical replica"] [traceID=523f606e4fa23962] [collectionID=438763080440024570] [partitionIDs="[438763080440024571]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(66d3b50ae876ac1b)] [msg="enqueue done"] [duration=278.024µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:816] ["start do subsearch"] [traceID=768cc85123de985f] [fromShardLeader=true] [vChannel=by-dev-rootcoord-dml_89_438763080440024570v26] [segmentIDs="[438763080441653034]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=713d3e5adf43d7aa] [msgID=438767653826068502] [segmentID=438763080440024596] [segmentType=3] [loadIndex=true]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(5037a6c77dfb4690)] [msg="enqueue done"] [duration=9.245µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(5037a6c77dfb4690)] [msg="enqueue done"] [duration=14.553µs]
[2023/01/15 06:56:09.320 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=1] [partitionIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=4c6daa0bd718d9b3] [vChannel=by-dev-rootcoord-dml_85_438763080440024570v22] [segmentIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=523f606e4fa23962] [msgID=438767653826068503] [segmentID=438763080441652843] [segmentType=3] [loadIndex=true]
[2023/01/15 06:56:09.320 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=5037a6c77dfb4690] [vChannel=by-dev-rootcoord-dml_87_438763080440024570v24] [segmentIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:855] ["start do search"] [traceID=4c6daa0bd718d9b3] [vChannel=by-dev-rootcoord-dml_91_438763080440024570v28] [segmentIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:816] ["start do subsearch"] [traceID=66d3b50ae876ac1b] [fromShardLeader=true] [vChannel=by-dev-rootcoord-dml_79_438763080440024570v16] [segmentIDs="[438763080441653118]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(768cc85123de985f)] [msg="enqueue done"] [duration=7.449µs]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:929] ["segments distribution"] [nodeID=15] [segments="[438763080441652637]"]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=1] [partitionIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=1] [partitionIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:927] ["cluster segment distribution"] [len=1] [partitionIDs="[]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(66d3b50ae876ac1b)] [msg="enqueue done"] [duration=5.595µs]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:929] ["segments distribution"] [nodeID=15] [segments="[438763080441653183]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/segment.go:330] ["start do search on segment"] [traceID=523f606e4fa23962] [msgID=438767653826068503] [segmentID=438763080441652972] [segmentType=3] [loadIndex=true]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:929] ["segments distribution"] [nodeID=15] [segments="[438763080441653160]"]
[2023/01/15 06:56:09.321 +00:00] [INFO] [querynode/shard_cluster.go:929] ["segments distribution"] [nodeID=15] [segments="[438763080441652972]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(768cc85123de985f)] [msg="enqueue done"] [duration=27.569µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:816] ["start do subsearch"] [traceID=5037a6c77dfb4690] [fromShardLeader=true] [vChannel=by-dev-rootcoord-dml_81_438763080440024570v18] [segmentIDs="[438763080441652637]"]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(5037a6c77dfb4690)] [msg="enqueue done"] [duration=11.049µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(5037a6c77dfb4690)] [msg="enqueue done"] [duration=4.598µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/task_read.go:78] [tr/searchTask(66d3b50ae876ac1b)] [msg="enqueue done"] [duration=18.769µs]
[2023/01/15 06:56:09.321 +00:00] [DEBUG] [querynode/impl.go:816] ["start do subsearch"] [traceID=4c6daa0bd718d9b3] [fromShardLeader=true] [vChannel=by-dev-rootcoord-dml_85_438763080440024570v22] [segmentIDs="[438763080441653183]"]
[2023/01/15 06:56:09.320 +00:00] [DEBUG] [querynode/impl.go:906] [tr/SearchShard] [traceID=2a01ed2e4445a893] [msg="do search done in shard cluster, vChannel = by-dev-rootcoord-dml_77_438763080440024570v14, segmentIDs = []"] [duration=2.010617ms]

CPU: Something I don't understand is that I can't get more QPS out of the systems and limit doesn't seem to be either CPU or I/O: image

Network I/O out: image

Network I/O in: image

Any idea what's going on?

ThomasAlxDmy avatar Jan 15 '23 07:01 ThomasAlxDmy

@ThomasAlxDmy thank you for the detailed feedbacks. According to the logs above, it looks like the bottleneck is not on querynode parts, but we still need to double confirm that with full milvus logs. So

  1. could you please offer all the miluvs pod logs, including proxy, querycoord, querynode, indexcoord, indexnode, rootcoord, etcd.
  2. Do you happen to have Milvus metrics with grafana, so that we can help you to address which phase the search costs most in milvus.
  3. could you please share the etcd backup with us to help us understand the segments status. please read https://github.com/milvus-io/birdwatcher/blob/main/README.md to backup etcd metadata

/assign @ThomasAlxDmy

yanliang567 avatar Jan 16 '23 02:01 yanliang567

Here's the etcd backup! (unfortunately cluster is ansible/terraform I haven't set up monitoring yet). bw_etcd_ALL.230118-181249.bak.gz

ThomasAlxDmy avatar Jan 19 '23 02:01 ThomasAlxDmy

/assign @liliu-z pls investigate on this issue when you have time

xiaofan-luan avatar Jan 19 '23 09:01 xiaofan-luan

@ThomasAlxDmy Just give a quick check if we still tracking here. Since I noticed we are communicating offline through email,

liliu-z avatar Feb 02 '23 02:02 liliu-z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions. Rotten issues close after 30d of inactivity. Reopen the issue with /reopen.

stale[bot] avatar Mar 17 '23 04:03 stale[bot]

/unassign

liliu-z avatar May 15 '23 03:05 liliu-z

/assign @zhagnlu

xiaofan-luan avatar May 15 '23 07:05 xiaofan-luan

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions. Rotten issues close after 30d of inactivity. Reopen the issue with /reopen.

stale[bot] avatar Aug 02 '23 14:08 stale[bot]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions. Rotten issues close after 30d of inactivity. Reopen the issue with /reopen.

stale[bot] avatar Sep 03 '23 19:09 stale[bot]