Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: [benchmark][standalone] search and query timeout #14077

Closed
1 task done
wangting0128 opened this issue Dec 23, 2021 · 34 comments
Closed
1 task done

[Bug]: [benchmark][standalone] search and query timeout #14077

wangting0128 opened this issue Dec 23, 2021 · 34 comments
Assignees
Labels
kind/bug Issues or changes related a bug test/benchmark benchmark test triage/accepted Indicates an issue or PR is ready to be actively worked on.
Milestone

Comments

@wangting0128
Copy link
Contributor

Is there an existing issue for this?

  • I have searched the existing issues

Environment

- Milvus version: master-20211222-1dab9cc
- Deployment mode(standalone or cluster): standalone
- SDK version(e.g. pymilvus v2.0.0rc2): 2.0.0rc9.dev22
- OS(Ubuntu or CentOS): 
- CPU/Memory: 
- GPU: 
- Others:

Current Behavior

client pod: benchmark-tag-bc6ld-3487203131

client logs:

[2021-12-23 04:22:46,616] [   DEBUG] - [scene_test] Start scene test : scene_test_5264_689522 (milvus_benchmark.client:505)
[2021-12-23 04:23:32,409] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640233366.604157093","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:17:46.603767', 'RPC start': '2021-12-23 04:17:46.603824', 'RPC error': '2021-12-23 04:23:32.409629'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:23:32,444] [   DEBUG] - Building index done, collection_name: scene_test_1802_167306, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 04:23:32,444] [   DEBUG] - Milvus create_index run in 612.8284s (milvus_benchmark.client:53)
[2021-12-23 04:23:32,445] [   DEBUG] - Building index done, collection_name: scene_test_8011_102868, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 04:23:32,445] [   DEBUG] - Milvus create_index run in 612.8278s (milvus_benchmark.client:53)
[2021-12-23 04:23:32,446] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640233126.633154575","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:17:46.632618', 'RPC start': '2021-12-23 04:17:46.632624', 'RPC error': '2021-12-23 04:23:32.446040'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:23:32,446] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640233126.633154575","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:13:24.925997', 'RPC start': '2021-12-23 04:13:24.926014', 'RPC error': '2021-12-23 04:23:32.446291'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:23:32,492] [   DEBUG] - Milvus load_collection run in 605.3294s (milvus_benchmark.client:53)
[2021-12-23 04:23:32,499] [   DEBUG] - Row count: 3000 in collection: <scene_test_2642_262496> (milvus_benchmark.client:421)
[2021-12-23 04:23:32,499] [   DEBUG] - [scene_test] Start create index : scene_test_2642_262496 (milvus_benchmark.client:519)
[2021-12-23 04:23:32,504] [    INFO] - Building index start, collection_name: scene_test_2642_262496, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 04:23:32,504] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 04:23:32,505] [   DEBUG] - collection: scene_test_2642_262496 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 04:23:32,507] [   DEBUG] - Milvus get_info run in 45.8987s (milvus_benchmark.client:53)
[2021-12-23 04:23:32,507] [   DEBUG] - [scene_test] Start insert : scene_test_1240_982971 (milvus_benchmark.client:512)
[2021-12-23 04:23:32,510] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:23:32,511] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:23:32,511] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:23:32,512] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:23:32,512] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:23:32,512] [    INFO] -  grpc scene_test                                                                    10112     0(0.00%)  |   82760   63128  386677   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:23:32,513] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:23:32,513] [    INFO] -  Aggregated                                                                         95321     0(0.00%)  |   11006       2  605335    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:23:32,513] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:23:32,513] [    INFO] - Create collection: <scene_test_5264_689522> successfully (milvus_benchmark.client:149)
[2021-12-23 04:23:32,514] [   DEBUG] - Milvus create_collection run in 45.8975s (milvus_benchmark.client:53)
[2021-12-23 04:23:32,514] [   DEBUG] - Milvus insert run in 606.3567s (milvus_benchmark.client:53)
[2021-12-23 04:23:32,514] [   DEBUG] - [scene_test] Start flush : scene_test_3944_481886 (milvus_benchmark.client:514)
[2021-12-23 04:28:32,517] [   DEBUG] - Drop collection scene_test_6326_526193 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,518] [   DEBUG] - Milvus drop run in 345.907s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,519] [   DEBUG] - [scene_test]Scene test close : scene_test_6326_526193 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,519] [   DEBUG] - Milvus scene_test run in 990.1005s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,520] [   DEBUG] - Drop collection scene_test_4829_118527 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,520] [   DEBUG] - Milvus drop run in 345.9084s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,520] [   DEBUG] - [scene_test]Scene test close : scene_test_4829_118527 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,521] [   DEBUG] - Milvus scene_test run in 964.011s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,521] [   DEBUG] - Drop collection scene_test_9575_358882 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,521] [   DEBUG] - Milvus drop run in 345.9092s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,522] [   DEBUG] - [scene_test]Scene test close : scene_test_9575_358882 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,522] [   DEBUG] - Milvus scene_test run in 957.3892s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,522] [   DEBUG] - Drop collection scene_test_624_241587 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,522] [   DEBUG] - Milvus drop run in 345.9095s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,523] [   DEBUG] - [scene_test]Scene test close : scene_test_624_241587 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,523] [   DEBUG] - Milvus scene_test run in 957.3819s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,523] [   DEBUG] - Drop collection scene_test_919_115405 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,523] [   DEBUG] - Milvus drop run in 345.9099s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,523] [   DEBUG] - [scene_test]Scene test close : scene_test_919_115405 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,524] [   DEBUG] - Milvus scene_test run in 951.5586s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,524] [   DEBUG] - Drop collection scene_test_5555_628482 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,524] [   DEBUG] - Milvus drop run in 345.9103s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,524] [   DEBUG] - [scene_test]Scene test close : scene_test_5555_628482 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,525] [   DEBUG] - Milvus scene_test run in 948.5807s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,525] [   DEBUG] - Drop collection scene_test_5944_87763 done. (milvus_benchmark.client:447)
[2021-12-23 04:28:32,525] [   DEBUG] - Milvus drop run in 345.9105s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,525] [   DEBUG] - [scene_test]Scene test close : scene_test_5944_87763 (milvus_benchmark.client:526)
[2021-12-23 04:28:32,525] [   DEBUG] - Milvus scene_test run in 946.3246s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,529] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:28:32,529] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:28:32,530] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:28:32,530] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:28:32,530] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:28:32,531] [    INFO] -  grpc scene_test                                                                    10119     0(0.00%)  |   83367   63128  990100   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:28:32,531] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:28:32,531] [    INFO] -  Aggregated                                                                         95328     0(0.00%)  |   11075       2  990100    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:28:32,531] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:28:32,531] [   DEBUG] - [scene_test] Start drop : scene_test_1802_167306 (milvus_benchmark.client:524)
[2021-12-23 04:28:32,532] [    INFO] - Start Drop collection: scene_test_1802_167306 (milvus_benchmark.client:429)
[2021-12-23 04:28:32,533] [   DEBUG] - [scene_test] Start drop : scene_test_8011_102868 (milvus_benchmark.client:524)
[2021-12-23 04:28:32,534] [    INFO] - Start Drop collection: scene_test_8011_102868 (milvus_benchmark.client:429)
[2021-12-23 04:28:32,535] [   DEBUG] - Milvus insert run in 645.9051s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,535] [   DEBUG] - [scene_test] Start flush : scene_test_1953_10987 (milvus_benchmark.client:514)
[2021-12-23 04:28:32,536] [   DEBUG] - Milvus insert run in 645.9056s (milvus_benchmark.client:53)
[2021-12-23 04:28:32,537] [   DEBUG] - [scene_test] Start flush : scene_test_7844_178763 (milvus_benchmark.client:514)
[2021-12-23 04:28:32,538] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640233712.516247870","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:23:32.515424', 'RPC start': '2021-12-23 04:23:32.515430', 'RPC error': '2021-12-23 04:28:32.538649'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:28:32,539] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640233472.517144719","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:23:32.516545', 'RPC start': '2021-12-23 04:23:32.516551', 'RPC error': '2021-12-23 04:28:32.539309'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:28:32,539] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640233472.517144719","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:17:46.607235', 'RPC start': '2021-12-23 04:17:46.607286', 'RPC error': '2021-12-23 04:28:32.539595'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:28:32,540] [   DEBUG] - [scene_test] Start scene test : scene_test_2447_699884 (milvus_benchmark.client:505)
[2021-12-23 04:28:32,542] [   DEBUG] - [scene_test] Start scene test : scene_test_7943_758126 (milvus_benchmark.client:505)
[2021-12-23 04:33:32,556] [   DEBUG] - Building index done, collection_name: scene_test_3157_90113, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 04:33:32,557] [   DEBUG] - Milvus create_index run in 1208.8143s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,558] [   DEBUG] - Milvus get_info run in 300.0294s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,558] [   DEBUG] - [scene_test] Start insert : scene_test_5264_689522 (milvus_benchmark.client:512)
[2021-12-23 04:33:32,561] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:33:32,562] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:33:32,562] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:33:32,562] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:33:32,562] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:33:32,563] [    INFO] -  grpc scene_test                                                                    10119     0(0.00%)  |   83367   63128  990100   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:33:32,563] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:33:32,563] [    INFO] -  Aggregated                                                                         95328     0(0.00%)  |   11075       2  990100    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:33:32,563] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:33:32,564] [   DEBUG] - Milvus insert run in 600.0561s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,564] [   DEBUG] - [scene_test] Start flush : scene_test_1240_982971 (milvus_benchmark.client:514)
[2021-12-23 04:33:32,565] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234012.541176037","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:28:32.540134', 'RPC start': '2021-12-23 04:28:32.540140', 'RPC error': '2021-12-23 04:33:32.565906'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:33:32,566] [    INFO] - Create collection: <scene_test_2447_699884> successfully (milvus_benchmark.client:149)
[2021-12-23 04:33:32,566] [   DEBUG] - Milvus create_collection run in 300.0258s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,567] [    INFO] - Create collection: <scene_test_7943_758126> successfully (milvus_benchmark.client:149)
[2021-12-23 04:33:32,567] [   DEBUG] - Milvus create_collection run in 300.0249s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,567] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234012.556189569","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:28:32.555369', 'RPC start': '2021-12-23 04:28:32.555376', 'RPC error': '2021-12-23 04:33:32.567544'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:33:32,567] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234012.556153669","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:28:32.555869', 'RPC start': '2021-12-23 04:28:32.555875', 'RPC error': '2021-12-23 04:33:32.567798'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:33:32,577] [   DEBUG] - Drop collection scene_test_1802_167306 done. (milvus_benchmark.client:447)
[2021-12-23 04:33:32,577] [   DEBUG] - Milvus drop run in 300.0456s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,577] [   DEBUG] - [scene_test]Scene test close : scene_test_1802_167306 (milvus_benchmark.client:526)
[2021-12-23 04:33:32,578] [   DEBUG] - Milvus scene_test run in 1234.4197s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,578] [   DEBUG] - Drop collection scene_test_8011_102868 done. (milvus_benchmark.client:447)
[2021-12-23 04:33:32,578] [   DEBUG] - Milvus drop run in 300.0444s (milvus_benchmark.client:53)
[2021-12-23 04:33:32,578] [   DEBUG] - [scene_test]Scene test close : scene_test_8011_102868 (milvus_benchmark.client:526)
[2021-12-23 04:33:32,579] [   DEBUG] - Milvus scene_test run in 1232.126s (milvus_benchmark.client:53)
[2021-12-23 04:38:32,588] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234072.581164386","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:33:32.580376', 'RPC start': '2021-12-23 04:33:32.580382', 'RPC error': '2021-12-23 04:38:32.587933'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:38:32,591] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234072.581164386","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:28:32.541721', 'RPC start': '2021-12-23 04:28:32.541727', 'RPC error': '2021-12-23 04:38:32.590763'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:38:32,595] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234072.583784208","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:33:32.581334', 'RPC start': '2021-12-23 04:33:32.581339', 'RPC error': '2021-12-23 04:38:32.594916'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:38:32,596] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234072.583784208","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:28:32.556371', 'RPC start': '2021-12-23 04:28:32.556377', 'RPC error': '2021-12-23 04:38:32.596470'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:38:32,603] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234312.583377847","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:33:32.582058', 'RPC start': '2021-12-23 04:33:32.582082', 'RPC error': '2021-12-23 04:38:32.603365'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:38:32,607] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234312.586420084","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:33:32.585492', 'RPC start': '2021-12-23 04:33:32.585564', 'RPC error': '2021-12-23 04:38:32.607694'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:38:32,609] [   DEBUG] - Milvus insert run in 300.0503s (milvus_benchmark.client:53)
[2021-12-23 04:38:32,609] [   DEBUG] - [scene_test] Start flush : scene_test_5264_689522 (milvus_benchmark.client:514)
[2021-12-23 04:38:32,625] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:38:32,625] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:38:32,626] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:38:32,626] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:38:32,627] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:38:32,628] [    INFO] -  grpc scene_test                                                                    10121     0(0.00%)  |   83594   63128 1234419   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:38:32,628] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:38:32,629] [    INFO] -  Aggregated                                                                         95330     0(0.00%)  |   11101       2 1234419    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:38:32,629] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:38:32,629] [   DEBUG] - [scene_test] Start drop : scene_test_3157_90113 (milvus_benchmark.client:524)
[2021-12-23 04:38:32,630] [    INFO] - Start Drop collection: scene_test_3157_90113 (milvus_benchmark.client:429)
[2021-12-23 04:43:32,625] [   DEBUG] - Milvus flush run in 1200.1105s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,627] [   DEBUG] - Milvus flush run in 900.0919s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,628] [   DEBUG] - Milvus flush run in 900.0911s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,630] [   DEBUG] - Building index done, collection_name: scene_test_2642_262496, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 04:43:32,630] [   DEBUG] - Milvus create_index run in 1200.1265s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,630] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234612.619203565","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:38:32.618621', 'RPC start': '2021-12-23 04:38:32.618627', 'RPC error': '2021-12-23 04:43:32.630741'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:43:32,631] [   DEBUG] - Milvus get_info run in 300.0113s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,631] [   DEBUG] - [scene_test] Start insert : scene_test_2447_699884 (milvus_benchmark.client:512)
[2021-12-23 04:43:32,632] [   DEBUG] - Milvus get_info run in 300.0105s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,633] [   DEBUG] - [scene_test] Start insert : scene_test_7943_758126 (milvus_benchmark.client:512)
[2021-12-23 04:43:32,633] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234612.625121273","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:38:32.624148', 'RPC start': '2021-12-23 04:38:32.624154', 'RPC error': '2021-12-23 04:43:32.633784'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:43:32,647] [   DEBUG] - Row count: 3000 in collection: <scene_test_3944_481886> (milvus_benchmark.client:421)
[2021-12-23 04:43:32,648] [   DEBUG] - [scene_test] Start create index : scene_test_3944_481886 (milvus_benchmark.client:519)
[2021-12-23 04:43:32,648] [    INFO] - Building index start, collection_name: scene_test_3944_481886, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 04:43:32,648] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 04:43:32,649] [   DEBUG] - collection: scene_test_3944_481886 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 04:43:32,652] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:43:32,653] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:43:32,653] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:43:32,654] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:43:32,654] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:43:32,654] [    INFO] -  grpc scene_test                                                                    10121     0(0.00%)  |   83594   63128 1234419   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:43:32,654] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:43:32,655] [    INFO] -  Aggregated                                                                         95330     0(0.00%)  |   11101       2 1234419    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:43:32,655] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:43:32,656] [   DEBUG] - Row count: 3000 in collection: <scene_test_1953_10987> (milvus_benchmark.client:421)
[2021-12-23 04:43:32,656] [   DEBUG] - [scene_test] Start create index : scene_test_1953_10987 (milvus_benchmark.client:519)
[2021-12-23 04:43:32,656] [    INFO] - Building index start, collection_name: scene_test_1953_10987, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 04:43:32,656] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 04:43:32,656] [   DEBUG] - collection: scene_test_1953_10987 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 04:43:32,657] [   DEBUG] - Row count: 3000 in collection: <scene_test_7844_178763> (milvus_benchmark.client:421)
[2021-12-23 04:43:32,657] [   DEBUG] - [scene_test] Start create index : scene_test_7844_178763 (milvus_benchmark.client:519)
[2021-12-23 04:43:32,658] [    INFO] - Building index start, collection_name: scene_test_7844_178763, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 04:43:32,658] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 04:43:32,658] [   DEBUG] - collection: scene_test_7844_178763 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 04:43:32,661] [   DEBUG] - Drop collection scene_test_3157_90113 done. (milvus_benchmark.client:447)
[2021-12-23 04:43:32,661] [   DEBUG] - Milvus drop run in 300.0318s (milvus_benchmark.client:53)
[2021-12-23 04:43:32,662] [   DEBUG] - [scene_test]Scene test close : scene_test_3157_90113 (milvus_benchmark.client:526)
[2021-12-23 04:43:32,662] [   DEBUG] - Milvus scene_test run in 1831.4244s (milvus_benchmark.client:53)
[2021-12-23 04:44:32,663] [   DEBUG] - Milvus flush run in 660.0985s (milvus_benchmark.client:53)
[2021-12-23 04:44:32,680] [   DEBUG] - Milvus flush run in 360.0707s (milvus_benchmark.client:53)
[2021-12-23 04:44:32,683] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234672.661140664","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:43:32.660081', 'RPC start': '2021-12-23 04:43:32.660087', 'RPC error': '2021-12-23 04:44:32.683008'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:44:32,685] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234672.661140664","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:38:32.619297', 'RPC start': '2021-12-23 04:38:32.619303', 'RPC error': '2021-12-23 04:44:32.685060'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:44:32,739] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:44:32,739] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:44:32,740] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:44:32,740] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:44:32,740] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:44:32,741] [    INFO] -  grpc scene_test                                                                    10122     0(0.00%)  |   83767   63128 1831424   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:44:32,741] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:44:32,741] [    INFO] -  Aggregated                                                                         95331     0(0.00%)  |   11120       2 1831424    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:44:32,742] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:44:32,742] [   DEBUG] - [scene_test] Start drop : scene_test_2642_262496 (milvus_benchmark.client:524)
[2021-12-23 04:44:32,742] [    INFO] - Start Drop collection: scene_test_2642_262496 (milvus_benchmark.client:429)
[2021-12-23 04:44:32,773] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234672.662121014","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:43:32.661280', 'RPC start': '2021-12-23 04:43:32.661285', 'RPC error': '2021-12-23 04:44:32.773803'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:44:32,774] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234672.662121014","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:38:32.624805', 'RPC start': '2021-12-23 04:38:32.624813', 'RPC error': '2021-12-23 04:44:32.774240'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:49:32,739] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234972.663240341","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:44:32.662621', 'RPC start': '2021-12-23 04:44:32.662633', 'RPC error': '2021-12-23 04:49:32.739698'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:49:32,741] [   DEBUG] - Row count: 3000 in collection: <scene_test_1240_982971> (milvus_benchmark.client:421)
[2021-12-23 04:49:32,741] [   DEBUG] - [scene_test] Start create index : scene_test_1240_982971 (milvus_benchmark.client:519)
[2021-12-23 04:49:32,742] [    INFO] - Building index start, collection_name: scene_test_1240_982971, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 04:49:32,742] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 04:49:32,742] [   DEBUG] - collection: scene_test_1240_982971 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 04:49:32,743] [   DEBUG] - Row count: 3000 in collection: <scene_test_5264_689522> (milvus_benchmark.client:421)
[2021-12-23 04:49:32,744] [   DEBUG] - [scene_test] Start create index : scene_test_5264_689522 (milvus_benchmark.client:519)
[2021-12-23 04:49:32,744] [    INFO] - Building index start, collection_name: scene_test_5264_689522, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 04:49:32,744] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 04:49:32,744] [   DEBUG] - collection: scene_test_5264_689522 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 04:49:32,746] [   DEBUG] - Milvus insert run in 360.1141s (milvus_benchmark.client:53)
[2021-12-23 04:49:32,746] [   DEBUG] - [scene_test] Start flush : scene_test_2447_699884 (milvus_benchmark.client:514)
[2021-12-23 04:49:32,747] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234972.737200348","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:44:32.736810', 'RPC start': '2021-12-23 04:44:32.736817', 'RPC error': '2021-12-23 04:49:32.747271'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:49:32,747] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234972.738150497","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:44:32.737921', 'RPC start': '2021-12-23 04:44:32.737927', 'RPC error': '2021-12-23 04:49:32.747683'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:49:32,748] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640234972.739133486","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:44:32.738488', 'RPC start': '2021-12-23 04:44:32.738494', 'RPC error': '2021-12-23 04:49:32.747987'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:49:32,748] [   DEBUG] - Milvus insert run in 360.1154s (milvus_benchmark.client:53)
[2021-12-23 04:49:32,748] [   DEBUG] - [scene_test] Start flush : scene_test_7943_758126 (milvus_benchmark.client:514)
[2021-12-23 04:49:32,754] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:49:32,754] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:49:32,754] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:49:32,755] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:49:32,755] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:49:32,755] [    INFO] -  grpc scene_test                                                                    10122     0(0.00%)  |   83767   63128 1831424   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:49:32,756] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:49:32,756] [    INFO] -  Aggregated                                                                         95331     0(0.00%)  |   11120       2 1831424    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:49:32,756] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:54:32,755] [   DEBUG] - Drop collection scene_test_2642_262496 done. (milvus_benchmark.client:447)
[2021-12-23 04:54:32,780] [   DEBUG] - Milvus drop run in 600.038s (milvus_benchmark.client:53)
[2021-12-23 04:54:32,780] [   DEBUG] - [scene_test]Scene test close : scene_test_2642_262496 (milvus_benchmark.client:526)
[2021-12-23 04:54:32,781] [   DEBUG] - Milvus scene_test run in 2486.5033s (milvus_benchmark.client:53)
[2021-12-23 04:54:32,782] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235272.752310273","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:49:32.751326', 'RPC start': '2021-12-23 04:49:32.751332', 'RPC error': '2021-12-23 04:54:32.782828'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:54:32,784] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235272.752259133","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:49:32.751901', 'RPC start': '2021-12-23 04:49:32.751907', 'RPC error': '2021-12-23 04:54:32.783934'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:54:32,797] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:54:32,798] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:54:32,798] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:54:32,798] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:54:32,799] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:54:32,799] [    INFO] -  grpc scene_test                                                                    10123     0(0.00%)  |   84004   63128 2486503   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:54:32,799] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:54:32,799] [    INFO] -  Aggregated                                                                         95332     0(0.00%)  |   11146       2 2486503    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:54:32,799] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:59:32,803] [   DEBUG] - Milvus flush run in 600.0565s (milvus_benchmark.client:53)
[2021-12-23 04:59:32,819] [   DEBUG] - Milvus flush run in 600.0706s (milvus_benchmark.client:53)
[2021-12-23 04:59:32,823] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235572.790272391","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:54:32.789878', 'RPC start': '2021-12-23 04:54:32.789909', 'RPC error': '2021-12-23 04:59:32.823651'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:59:32,824] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235572.797319665","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:54:32.796845', 'RPC start': '2021-12-23 04:54:32.796852', 'RPC error': '2021-12-23 04:59:32.824283'} (pymilvus.client.grpc_handler:84)
[2021-12-23 04:59:32,827] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 04:59:32,828] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 04:59:32,828] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:59:32,828] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:59:32,829] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:59:32,829] [    INFO] -  grpc scene_test                                                                    10123     0(0.00%)  |   84004   63128 2486503   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 04:59:32,829] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 04:59:32,829] [    INFO] -  Aggregated                                                                         95332     0(0.00%)  |   11146       2 2486503    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 04:59:32,829] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 04:59:32,834] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235572.801308527","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:54:32.800971', 'RPC start': '2021-12-23 04:54:32.800977', 'RPC error': '2021-12-23 04:59:32.834235'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:00:32,825] [   DEBUG] - Row count: 3000 in collection: <scene_test_2447_699884> (milvus_benchmark.client:421)
[2021-12-23 05:00:33,200] [   DEBUG] - [scene_test] Start create index : scene_test_2447_699884 (milvus_benchmark.client:519)
[2021-12-23 05:00:33,202] [    INFO] - Building index start, collection_name: scene_test_2447_699884, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 05:00:33,204] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 05:00:33,206] [   DEBUG] - collection: scene_test_2447_699884 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 05:00:33,212] [   DEBUG] - Row count: 3000 in collection: <scene_test_7943_758126> (milvus_benchmark.client:421)
[2021-12-23 05:00:33,236] [   DEBUG] - [scene_test] Start create index : scene_test_7943_758126 (milvus_benchmark.client:519)
[2021-12-23 05:00:33,236] [    INFO] - Building index start, collection_name: scene_test_7943_758126, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2021-12-23 05:00:33,237] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2021-12-23 05:00:33,237] [   DEBUG] - collection: scene_test_7943_758126 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2021-12-23 05:00:33,238] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235632.823167864","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:59:32.822533', 'RPC start': '2021-12-23 04:59:32.822540', 'RPC error': '2021-12-23 05:00:33.238521'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:00:33,238] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235632.823167864","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:49:32.750126', 'RPC start': '2021-12-23 04:49:32.750132', 'RPC error': '2021-12-23 05:00:33.238847'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:00:33,239] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235632.824134188","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:59:32.823354', 'RPC start': '2021-12-23 04:59:32.823359', 'RPC error': '2021-12-23 05:00:33.239193'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:00:33,239] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235632.824134188","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:49:32.750731', 'RPC start': '2021-12-23 04:49:32.750737', 'RPC error': '2021-12-23 05:00:33.239646'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:00:33,252] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-23 05:00:33,253] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-23 05:00:33,253] [    INFO] -  grpc get                                                                           39823     0(0.00%)  |    2044     981  259468    2000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 05:00:33,254] [    INFO] -  grpc load_collection                                                                5073     0(0.00%)  |    2044       2  605335    1500  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 05:00:33,254] [    INFO] -  grpc query                                                                         40313     0(0.00%)  |    2987     155   15437    2600  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 05:00:33,255] [    INFO] -  grpc scene_test                                                                    10123     0(0.00%)  |   84004   63128 2486503   82000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-23 05:00:33,255] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-23 05:00:33,255] [    INFO] -  Aggregated                                                                         95332     0(0.00%)  |   11146       2 2486503    2200  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-23 05:00:33,255] [    INFO] -  (locust.stats_logger:733)
[2021-12-23 05:05:33,251] [   DEBUG] - Building index done, collection_name: scene_test_3944_481886, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 05:05:33,252] [   DEBUG] - Milvus create_index run in 1320.6044s (milvus_benchmark.client:53)
[2021-12-23 05:05:33,253] [   DEBUG] - Building index done, collection_name: scene_test_1953_10987, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 05:05:33,254] [   DEBUG] - Milvus create_index run in 1320.5975s (milvus_benchmark.client:53)
[2021-12-23 05:05:33,254] [   DEBUG] - Building index done, collection_name: scene_test_7844_178763, response: Status(code=0, message='') (milvus_benchmark.client:284)
[2021-12-23 05:05:33,254] [   DEBUG] - Milvus create_index run in 1320.5968s (milvus_benchmark.client:53)
[2021-12-23 05:05:33,255] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235933.248149882","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 05:00:33.247536', 'RPC start': '2021-12-23 05:00:33.247543', 'RPC error': '2021-12-23 05:05:33.255242'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:05:33,255] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235933.250196955","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 05:00:33.249105', 'RPC start': '2021-12-23 05:00:33.249111', 'RPC error': '2021-12-23 05:05:33.255918'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:05:33,256] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235933.250155375","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 05:00:33.249672', 'RPC start': '2021-12-23 05:00:33.249678', 'RPC error': '2021-12-23 05:05:33.256503'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:05:33,256] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235933.251131414","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 05:00:33.250222', 'RPC start': '2021-12-23 05:00:33.250228', 'RPC error': '2021-12-23 05:05:33.256847'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:05:33,257] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235693.258181166","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 05:00:33.257585', 'RPC start': '2021-12-23 05:00:33.257590', 'RPC error': '2021-12-23 05:05:33.257963'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:05:33,258] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640235693.258181166","description":"Error received from peer ipv4:10.96.42.187:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-23 04:59:32.826820', 'RPC start': '2021-12-23 04:59:32.826826', 'RPC error': '2021-12-23 05:05:33.258438'} (pymilvus.client.grpc_handler:84)
[2021-12-23 05:05:33,259] [   ERROR] - 
Addr [benchmark-tag-bc6ld-1-milvus.qa-milvus.svc.cluster.local:19

Expected Behavior

argo task: benchmark-tag-bc6ld

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m

server:

NAME                                                             READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-bc6ld-1-etcd-0                                     1/1     Running     0          20h    10.97.17.75    qa-node014.zilliz.local   <none>           <none>
benchmark-tag-bc6ld-1-milvus-standalone-59cbdc47bb-gs6xb         1/1     Running     0          20h    10.97.20.190   qa-node018.zilliz.local   <none>           <none>
benchmark-tag-bc6ld-1-minio-8486ccdd6d-m7zh2                     1/1     Running     0          20h    10.97.12.41    qa-node015.zilliz.local   <none>           <none>

Steps To Reproduce

1、create collation
2、build index of ivf_sq8
3、insert 100 million vectors
4、flush collection
5、build index with the same params
6、load collection
7、locust concurrent: query<-search, load, get<-query, scene_test

Anything else?

client-random-locust-100m-ddl-r8-w2:

locust_random_performance:
      collections:
        -
          collection_name: sift_100m_128_l2
          ni_per: 50000
          build_index: true
          index_type: ivf_sq8
          index_param:
            nlist: 2048
          task:
            types:
              -
                type: query
                weight: 8
                params:
                  top_k: 10
                  nq: 10
                  search_param:
                    nprobe: 16
              -
                type: load
                weight: 1
              -
                type: get
                weight: 8
                params:
                  ids_length: 10
              -
                type: scene_test
                weight: 2
            connection_num: 1
            clients_num: 20
            spawn_rate: 2
            during_time: 302400

scene_test:

    def scene_test(self, collection_name=None, vectors=None, ids=None):
        logger.debug("[scene_test] Start scene test : %s" % collection_name)
        self.create_collection(dimension=128, collection_name=collection_name)
        time.sleep(1)

        collection_info = self.get_info(collection_name)

        entities = utils.generate_entities(collection_info, vectors, ids)
        logger.debug("[scene_test] Start insert : %s" % collection_name)
        self.insert(entities, collection_name=collection_name)
        logger.debug("[scene_test] Start flush : %s" % collection_name)
        self.flush(collection_name=collection_name)

        self.count(collection_name=collection_name)

        logger.debug("[scene_test] Start create index : %s" % collection_name)
        self.create_index(field_name='float_vector', index_type="ivf_sq8", metric_type='l2',
                          collection_name=collection_name, index_param={'nlist': 2048})
        time.sleep(59)

        logger.debug("[scene_test] Start drop : %s" % collection_name)
        self.drop(collection_name=collection_name)
        logger.debug("[scene_test]Scene test close : %s" % collection_name)
@wangting0128 wangting0128 added kind/bug Issues or changes related a bug priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. test/benchmark benchmark test labels Dec 23, 2021
@yanliang567
Copy link
Contributor

@xige-16 please help on this issue
/assign @xige-16
/unassign

@sre-ci-robot sre-ci-robot assigned xige-16 and unassigned yanliang567 Dec 23, 2021
@yanliang567 yanliang567 added this to the 2.0.0-GA milestone Dec 23, 2021
@xige-16
Copy link
Contributor

xige-16 commented Dec 24, 2021

rocksmq produce msg too slow

[2021/12/23 04:27:46.434 +00:00] [WARN] [rocksmq_impl.go:573] ["rocksmq produce too slowly"] [topic=by-dev-rootcoord-dml_0] ["get lock elapse"=15678] ["alloc elapse"=15678] ["write elapse"=15678] ["updatePage elapse"=15678]

rocksmq consume msg too slow

[2021/12/23 04:27:53.887 +00:00] [WARN] [rocksmq_impl.go:707] ["rocksmq consume too slowly"] [topic=by-dev-rootcoord-dml_0] ["get lock elapse"=6666] ["consume elapse"=14119]
[2021/12/23 04:27:53.887 +00:00] [DEBUG] [query_collection.go:595] ["get query message from unsolvedMsg"] [collectionID=429961324153474369] [msgID=429977092482057991] [reqTime_p=2021/12/23 04:23:32.472 +00:00] [serviceTime_p=2021/12/23 04:21:38.222 +00:00] [guaranteeTime_l=429977347679059981] [serviceTime_l=429977317729107969]
[2021/12/23 04:27:57.152 +00:00] [DEBUG] [index_coord.go:698] ["IndexCoord recycleUnusedIndexFiles"] ["Need recycle tasks num"=0]
[2021/12/23 04:28:01.046 +00:00] [WARN] [timeticksync.go:318] ["rootcoord send tt to all channels too slowly"] [chanNum=32] [span=14612]

querynode first receive a query msg

[2021/12/23 04:23:32.519 +00:00] [DEBUG] [query_collection.go:504] ["query node::receiveQueryMsg: add to unsolvedMsg"] [collectionID=429961324153474369] [sm.GuaranteeTimestamp=2021/12/23 04:23:32.472 +00:00] [serviceTime=2021/12/23 04:17:45.522 +00:00] ["delta seconds"=90] [msgID=429977092482057991] [msgType=retrieve]

querynode wait to query msg timeout

[2021/12/23 04:28:37.976 +00:00] [DEBUG] [query_collection.go:595] ["get query message from unsolvedMsg"] [collectionID=429961324153474369] [msgID=429977092482057991] [reqTime_p=2021/12/23 04:23:32.472 +00:00] [serviceTime_p=2021/12/23 04:22:35.422 +00:00] [guaranteeTime_l=429977347679059981] [serviceTime_l=429977332723744769]
[2021/12/23 04:28:37.976 +00:00] [DEBUG] [flow_graph_dd_node.go:272] ["ddNode add flushed segment"] [collectionID=429977347652845570] ["No. Segment"=0]
[2021/12/23 04:28:37.976 +00:00] [WARN] [timeticksync.go:318] ["rootcoord send tt to all channels too slowly"] [chanNum=32] [span=18805]
[2021/12/23 04:28:37.976 +00:00] [WARN] [query_collection.go:608] ["do query failed in doUnsolvedQueryMsg because timeout, collectionID =  429961324153474369 , msgID =  429977092482057991\n"]

@xige-16
Copy link
Contributor

xige-16 commented Dec 24, 2021

rocksmq produce msg too slow

[2021/12/23 04:27:46.434 +00:00] [WARN] [rocksmq_impl.go:573] ["rocksmq produce too slowly"] [topic=by-dev-rootcoord-dml_0] ["get lock elapse"=15678] ["alloc elapse"=15678] ["write elapse"=15678] ["updatePage elapse"=15678]

rocksmq consume msg too slow

[2021/12/23 04:27:53.887 +00:00] [WARN] [rocksmq_impl.go:707] ["rocksmq consume too slowly"] [topic=by-dev-rootcoord-dml_0] ["get lock elapse"=6666] ["consume elapse"=14119]
[2021/12/23 04:27:53.887 +00:00] [DEBUG] [query_collection.go:595] ["get query message from unsolvedMsg"] [collectionID=429961324153474369] [msgID=429977092482057991] [reqTime_p=2021/12/23 04:23:32.472 +00:00] [serviceTime_p=2021/12/23 04:21:38.222 +00:00] [guaranteeTime_l=429977347679059981] [serviceTime_l=429977317729107969]
[2021/12/23 04:27:57.152 +00:00] [DEBUG] [index_coord.go:698] ["IndexCoord recycleUnusedIndexFiles"] ["Need recycle tasks num"=0]
[2021/12/23 04:28:01.046 +00:00] [WARN] [timeticksync.go:318] ["rootcoord send tt to all channels too slowly"] [chanNum=32] [span=14612]

querynode first receive a query msg

[2021/12/23 04:23:32.519 +00:00] [DEBUG] [query_collection.go:504] ["query node::receiveQueryMsg: add to unsolvedMsg"] [collectionID=429961324153474369] [sm.GuaranteeTimestamp=2021/12/23 04:23:32.472 +00:00] [serviceTime=2021/12/23 04:17:45.522 +00:00] ["delta seconds"=90] [msgID=429977092482057991] [msgType=retrieve]

querynode wait to query msg timeout

[2021/12/23 04:28:37.976 +00:00] [DEBUG] [query_collection.go:595] ["get query message from unsolvedMsg"] [collectionID=429961324153474369] [msgID=429977092482057991] [reqTime_p=2021/12/23 04:23:32.472 +00:00] [serviceTime_p=2021/12/23 04:22:35.422 +00:00] [guaranteeTime_l=429977347679059981] [serviceTime_l=429977332723744769]
[2021/12/23 04:28:37.976 +00:00] [DEBUG] [flow_graph_dd_node.go:272] ["ddNode add flushed segment"] [collectionID=429977347652845570] ["No. Segment"=0]
[2021/12/23 04:28:37.976 +00:00] [WARN] [timeticksync.go:318] ["rootcoord send tt to all channels too slowly"] [chanNum=32] [span=18805]
[2021/12/23 04:28:37.976 +00:00] [WARN] [query_collection.go:608] ["do query failed in doUnsolvedQueryMsg because timeout, collectionID =  429961324153474369 , msgID =  429977092482057991\n"]

It seems that rockdb is too slow to access the disk

@xige-16
Copy link
Contributor

xige-16 commented Dec 24, 2021

etcd log is normal, it should not be etcd which caused the slow sending of timtick

"level":"info","ts":"2021-12-23T04:17:00.571Z","caller":"v3compactor/revision.go:94","msg":"completed auto revision compaction","revision":545410,"revision-compaction-retention":1000,"took":"581.956碌s"}
{"level":"info","ts":"2021-12-23T04:17:00.570Z","caller":"v3compactor/revision.go:86","msg":"starting auto revision compaction","revision":545410,"revision-compaction-retention":1000}
{"level":"info","ts":"2021-12-23T04:17:00.571Z","caller":"mvcc/index.go:214","msg":"compact tree index","revision":545410}
{"level":"info","ts":"2021-12-23T04:17:01.533Z","caller":"mvcc/kvstore_compaction.go:57","msg":"finished scheduled compaction","compact-revision":545410,"took":"895.518243ms"}
{"level":"info","ts":"2021-12-23T04:22:00.571Z","caller":"v3compactor/revision.go:86","msg":"starting auto revision compaction","revision":545743,"revision-compaction-retention":1000}
{"level":"info","ts":"2021-12-23T04:22:00.572Z","caller":"mvcc/index.go:214","msg":"compact tree index","revision":545743}
{"level":"info","ts":"2021-12-23T04:22:00.572Z","caller":"v3compactor/revision.go:94","msg":"completed auto revision compaction","revision":545743,"revision-compaction-retention":1000,"took":"441.294碌s"}
{"level":"info","ts":"2021-12-23T04:22:01.329Z","caller":"mvcc/kvstore_compaction.go:57","msg":"finished scheduled compaction","compact-revision":545743,"took":"687.84808ms"}
{"level":"info","ts":"2021-12-23T04:27:00.572Z","caller":"v3compactor/revision.go:86","msg":"starting auto revision compaction","revision":546233,"revision-compaction-retention":1000}
{"level":"info","ts":"2021-12-23T04:27:00.572Z","caller":"v3compactor/revision.go:94","msg":"completed auto revision compaction","revision":546233,"revision-compaction-retention":1000,"took":"505.175碌s"}
{"level":"info","ts":"2021-12-23T04:27:00.572Z","caller":"mvcc/index.go:214","msg":"compact tree index","revision":546233}
{"level":"info","ts":"2021-12-23T04:27:01.338Z","caller":"mvcc/kvstore_compaction.go:57","msg":"finished scheduled compaction","compact-revision":546233,"took":"710.944404ms"}

@xige-16
Copy link
Contributor

xige-16 commented Dec 24, 2021

Rocksmq produce and consume both took a lot of time to get lock

@wangting0128
Copy link
Contributor Author

argo task: benchmark-tag-cnrlf

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m

server:

NAME                                                             READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-cnrlf-1-etcd-0                                     1/1     Running     0          23h    10.97.16.155   qa-node013.zilliz.local   <none>           <none>
benchmark-tag-cnrlf-1-milvus-standalone-b7dc7898f-st5tz          1/1     Running     0          23h    10.97.17.178   qa-node014.zilliz.local   <none>           <none>
benchmark-tag-cnrlf-1-minio-54cd5b85bf-2tnnl                     1/1     Running     0          23h    10.97.19.134   qa-node016.zilliz.local   <none>           <none>

client pod: benchmark-tag-cnrlf-3228498151

client log:

[2021-12-24 03:50:10,247] [   DEBUG] - Milvus get run in 1.0301s (milvus_benchmark.client:53)
[2021-12-24 03:52:49,275] [   ERROR] - 
Addr [benchmark-tag-cnrlf-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640317870.253881047","description":"Error received from peer ipv4:10.96.69.145:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-24 03:50:10.249280', 'RPC start': '2021-12-24 03:50:10.249289', 'RPC error': '2021-12-24 03:52:49.274735'} (pymilvus.client.grpc_handler:84)
[2021-12-24 03:52:49,287] [   ERROR] - 
Addr [benchmark-tag-cnrlf-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640317870.253881047","description":"Error received from peer ipv4:10.96.69.145:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-24 03:50:08.167147', 'RPC start': '2021-12-24 03:50:08.167160', 'RPC error': '2021-12-24 03:52:49.287752'} (pymilvus.client.grpc_handler:84)
[2021-12-24 03:52:49,289] [   DEBUG] - Milvus get run in 159.0394s (milvus_benchmark.client:53)
[2021-12-24 03:52:49,290] [   ERROR] - 
Addr [benchmark-tag-cnrlf-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640317870.254174659","description":"Error received from peer ipv4:10.96.69.145:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-24 03:50:10.251238', 'RPC start': '2021-12-24 03:50:10.251247', 'RPC error': '2021-12-24 03:52:49.290732'} (pymilvus.client.grpc_handler:84)
[2021-12-24 03:52:49,291] [   ERROR] - 
Addr [benchmark-tag-cnrlf-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640317870.254174659","description":"Error received from peer ipv4:10.96.69.145:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-24 03:50:08.169089', 'RPC start': '2021-12-24 03:50:08.169099', 'RPC error': '2021-12-24 03:52:49.291326'} (pymilvus.client.grpc_handler:84)
[2021-12-24 03:52:49,292] [   ERROR] - 
Addr [benchmark-tag-cnrlf-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640317930.258980024","description":"Error received from peer ipv4:10.96.69.145:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-24 03:51:10.258355', 'RPC start': '2021-12-24 03:51:10.258373', 'RPC error': '2021-12-24 03:52:49.292581'} (pymilvus.client.grpc_handler:84)
[2021-12-24 03:52:49,293] [   ERROR] - 
Addr [benchmark-tag-cnrlf-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640317930.258980024","description":"Error received from peer ipv4:10.96.69.145:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-24 03:50:08.170588', 'RPC start': '2021-12-24 03:50:08.170597', 'RPC error': '2021-12-24 03:52:49.293130'} (pymilvus.client.grpc_handler:84)

@wangting0128
Copy link
Contributor Author

Using local-path

argo task: benchmark-tag-dcmmg

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m-localpath

server:

standalone:
  affinity: {}
  extraEnv: []
  nodeSelector:
    disk: large
  persistence:
    annotations: {}
    enabled: true
    mountPath: /var/lib/milvus
    persistentVolumeClaim:
      accessModes: ReadWriteOnce
      existingClaim: ""
      size: 200Gi
      storageClass: local-path
      subPath: ""
  replicas: 1
  resources:
    limits:
      cpu: "32.0"
      memory: 128Gi
    requests:
      cpu: "17.0"
      memory: 65Gi
NAME                                                             READY   STATUS      RESTARTS   AGE     IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-dcmmg-1-etcd-0                                     1/1     Running     0          19h     10.97.16.96    qa-node013.zilliz.local   <none>           <none>
benchmark-tag-dcmmg-1-milvus-standalone-d6fcb8598-sn8lq          1/1     Running     0          19h     10.97.20.247   qa-node018.zilliz.local   <none>           <none>
benchmark-tag-dcmmg-1-minio-d5dbcd7c8-jb7lh                      1/1     Running     0          19h     10.97.19.237   qa-node016.zilliz.local   <none>           <none>

client pod: benchmark-tag-dcmmg-2773654560

client log:

[2021-12-25 03:50:46,090] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.055862896","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.055103', 'RPC start': '2021-12-25 03:45:46.055113', 'RPC error': '2021-12-25 03:50:46.089971'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:50:46,091] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.057814956","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.057104', 'RPC start': '2021-12-25 03:45:46.057113', 'RPC error': '2021-12-25 03:50:46.090948'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:50:46,091] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.058804519","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.058149', 'RPC start': '2021-12-25 03:45:46.058160', 'RPC error': '2021-12-25 03:50:46.091592'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:50:46,092] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.059765089","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.059106', 'RPC start': '2021-12-25 03:45:46.059115', 'RPC error': '2021-12-25 03:50:46.092167'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:50:46,093] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2021-12-25 03:50:46,094] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2021-12-25 03:50:46,095] [    INFO] -  grpc get                                                                           37959     0(0.00%)  |    2244    1030    7856    2200  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-25 03:50:46,095] [    INFO] -  grpc load_collection                                                                4905     0(0.00%)  |    2275       3   11203    1900  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-25 03:50:46,096] [    INFO] -  grpc query                                                                         37782     0(0.00%)  |    3539      72   16523    3200  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-25 03:50:46,096] [    INFO] -  grpc scene_test                                                                     9551     0(0.00%)  |   84953   64208  153460   85000  |    0.00    0.00 (locust.stats_logger:730)
[2021-12-25 03:50:46,097] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2021-12-25 03:50:46,097] [    INFO] -  Aggregated                                                                         90197     0(0.00%)  |   11546       3  153460    2500  |    0.00    0.00 (locust.stats_logger:732)
[2021-12-25 03:50:46,098] [    INFO] -  (locust.stats_logger:733)
[2021-12-25 03:50:46,099] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.061803623","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.061176', 'RPC start': '2021-12-25 03:45:46.061185', 'RPC error': '2021-12-25 03:50:46.099242'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:50:46,100] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.063785085","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.063117', 'RPC start': '2021-12-25 03:45:46.063126', 'RPC error': '2021-12-25 03:50:46.100448'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:50:46,101] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404246.076797055","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.076117', 'RPC start': '2021-12-25 03:45:46.076126', 'RPC error': '2021-12-25 03:50:46.101798'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,118] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.106788918","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.105869', 'RPC start': '2021-12-25 03:50:46.105878', 'RPC error': '2021-12-25 03:51:46.118102'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,121] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.106788918","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.048477', 'RPC start': '2021-12-25 03:45:46.048489', 'RPC error': '2021-12-25 03:51:46.121281'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,122] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.107794379","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.107039', 'RPC start': '2021-12-25 03:50:46.107048', 'RPC error': '2021-12-25 03:51:46.122368'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,123] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.107794379","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.051372', 'RPC start': '2021-12-25 03:45:46.051382', 'RPC error': '2021-12-25 03:51:46.123285'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,124] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.108796262","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.108170', 'RPC start': '2021-12-25 03:50:46.108179', 'RPC error': '2021-12-25 03:51:46.124346'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,125] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.108796262","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.053022', 'RPC start': '2021-12-25 03:45:46.053032', 'RPC error': '2021-12-25 03:51:46.125345'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,126] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.109771561","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.109287', 'RPC start': '2021-12-25 03:50:46.109296', 'RPC error': '2021-12-25 03:51:46.126371'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,127] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.109771561","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.053952', 'RPC start': '2021-12-25 03:45:46.053961', 'RPC error': '2021-12-25 03:51:46.127496'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,128] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.110787168","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.110409', 'RPC start': '2021-12-25 03:50:46.110417', 'RPC error': '2021-12-25 03:51:46.128665'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,129] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.110787168","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.056071', 'RPC start': '2021-12-25 03:45:46.056081', 'RPC error': '2021-12-25 03:51:46.129907'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,130] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.111782281","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.111590', 'RPC start': '2021-12-25 03:50:46.111599', 'RPC error': '2021-12-25 03:51:46.130754'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,131] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.111782281","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.060198', 'RPC start': '2021-12-25 03:45:46.060208', 'RPC error': '2021-12-25 03:51:46.131727'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,134] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.113780106","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.113519', 'RPC start': '2021-12-25 03:50:46.113527', 'RPC error': '2021-12-25 03:51:46.134261'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,135] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.113780106","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.062234', 'RPC start': '2021-12-25 03:45:46.062243', 'RPC error': '2021-12-25 03:51:46.135175'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,136] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.115781707","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.114749', 'RPC start': '2021-12-25 03:50:46.114776', 'RPC error': '2021-12-25 03:51:46.136105'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,136] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.115781707","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.074094', 'RPC start': '2021-12-25 03:45:46.074105', 'RPC error': '2021-12-25 03:51:46.136930'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,137] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.116823835","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.116051', 'RPC start': '2021-12-25 03:50:46.116060', 'RPC error': '2021-12-25 03:51:46.137787'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,138] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.116823835","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.075082', 'RPC start': '2021-12-25 03:45:46.075091', 'RPC error': '2021-12-25 03:51:46.138665'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,139] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.117798176","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:50:46.117204', 'RPC start': '2021-12-25 03:50:46.117212', 'RPC error': '2021-12-25 03:51:46.139756'} (pymilvus.client.grpc_handler:84)
[2021-12-25 03:51:46,140] [   ERROR] - 
Addr [benchmark-tag-dcmmg-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1640404306.117798176","description":"Error received from peer ipv4:10.96.238.203:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2021-12-25 03:45:46.077055', 'RPC start': '2021-12-25 03:45:46.077067', 'RPC error': '2021-12-25 03:51:46.140612'} (pymilvus.client.grpc_handler:84)

@xige-16
Copy link
Contributor

xige-16 commented Dec 28, 2021

/unassign

@xiaofan-luan
Copy link
Collaborator

are we still hitting the same issue after the fix @wangting0128

@xiaofan-luan
Copy link
Collaborator

/assign @wangting0128

@yanliang567 yanliang567 added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Jan 4, 2022
@wangting0128
Copy link
Contributor Author

Recoverable after query and search failure

argo task: benchmark-px6ww

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m

server:

NAME                                                              READY   STATUS             RESTARTS   AGE     IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-px6ww-1-etcd-0                                          1/1     Running            0          14h     10.97.17.193   qa-node014.zilliz.local   <none>           <none>
benchmark-px6ww-1-milvus-standalone-84bc54dd8d-skkjt              1/1     Running            1          14h     10.97.20.198   qa-node018.zilliz.local   <none>           <none>
benchmark-px6ww-1-minio-74bf9d588c-nvwl4                          1/1     Running            0          14h     10.97.20.199   qa-node018.zilliz.local   <none>           <none>

client pod: benchmark-px6ww-1300394705

client log:

[2022-01-04 13:03:06,969] [   ERROR] - 
Addr [benchmark-px6ww-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Connection reset by peer"
	debug_error_string = "{"created":"@1641301386.968059151","description":"Error received from peer ipv4:10.96.30.186:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Connection reset by peer","grpc_status":14}"
>
	{'API start': '2022-01-04 13:03:00.463522', 'RPC start': '2022-01-04 13:03:00.463528', 'RPC error': '2022-01-04 13:03:06.969768'} (pymilvus.client.grpc_handler:84)
[2022-01-04 13:03:06,970] [   ERROR] - 
Addr [benchmark-px6ww-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Connection reset by peer"
	debug_error_string = "{"created":"@1641301386.968059151","description":"Error received from peer ipv4:10.96.30.186:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Connection reset by peer","grpc_status":14}"
>
	{'API start': '2022-01-04 13:02:59.273608', 'RPC start': '2022-01-04 13:02:59.273614', 'RPC error': '2022-01-04 13:03:06.970378'} (pymilvus.client.grpc_handler:84)
[2022-01-04 13:08:06,970] [   DEBUG] - Ramping to {"MyUser": 8} (8 total users) (locust.runners:326)
[2022-01-04 13:08:06,972] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 6} already running)... (locust.runners:202)
[2022-01-04 13:08:06,972] [   DEBUG] - 8 users spawned (locust.runners:212)
[2022-01-04 13:08:06,972] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-04 13:08:06,973] [   DEBUG] - 0 users have been stopped, 8 still running (locust.runners:271)
[2022-01-04 13:08:06,974] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-04 13:08:06,974] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-04 13:08:06,974] [    INFO] -  grpc get                                                                               5     0(0.00%)  |    1619    1129    2279    1200  |    0.40    0.00 (locust.stats_logger:730)
[2022-01-04 13:08:06,975] [    INFO] -  grpc load_collection                                                                   1     0(0.00%)  |    1192    1192    1192    1192  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-04 13:08:06,975] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-04 13:08:06,975] [    INFO] -  Aggregated                                                                             6     0(0.00%)  |    1547    1129    2279    1200  |    0.40    0.00 (locust.stats_logger:732)
[2022-01-04 13:08:06,976] [    INFO] -  (locust.stats_logger:733)
[2022-01-04 13:08:06,976] [   ERROR] - 
Addr [benchmark-px6ww-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641301686.969084089","description":"Error received from peer ipv4:10.96.30.186:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-04 13:03:06.968857', 'RPC start': '2022-01-04 13:03:06.968871', 'RPC error': '2022-01-04 13:08:06.976714'} (pymilvus.client.grpc_handler:84)
[2022-01-04 13:08:06,982] [   DEBUG] - Milvus get_info run in 0.0126s (milvus_benchmark.client:53)

@xiaofan-luan
Copy link
Collaborator

@bigsheeper
Copy link
Contributor

the querynode crash while doing search, @bigsheeper any idea on this? image

Can't find the cause from the stack trace log, try to reproduce on my computer, and execute from step 1 to step 6 mentioned above, then keep loading collection and doing search concurrently by 50 threads. QueryNode doesn't crash.

@xige-16
Copy link
Contributor

xige-16 commented Jan 7, 2022

@wangting0128
Copy link
Contributor Author

argo task: benchmark-no-clean-kxmp4

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m

server:

NAME                                                             READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-no-clean-kxmp4-1-etcd-0                                1/1     Running     0          13h    10.97.17.186   qa-node014.zilliz.local   <none>           <none>
benchmark-no-clean-kxmp4-1-milvus-standalone-9fdc7b6dc-7qbp2     1/1     Running     1          13h    10.97.16.218   qa-node013.zilliz.local   <none>           <none>
benchmark-no-clean-kxmp4-1-minio-66bdfb668f-nzrtf                1/1     Running     0          13h    10.97.12.75    qa-node015.zilliz.local   <none>           <none>

client pod: benchmark-no-clean-kxmp4-1560983271

locust_report_2022-01-10_119.log

client logs:

Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Connection reset by peer"
	debug_error_string = "{"created":"@1641826386.817524475","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Connection reset by peer","grpc_status":14}"
>
	{'API start': '2022-01-10 14:52:58.298021', 'RPC start': '2022-01-10 14:52:58.298064', 'RPC error': '2022-01-10 14:53:06.819642'} (pymilvus.client.grpc_handler:86)
[2022-01-10 14:53:06,821] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Connection reset by peer"
	debug_error_string = "{"created":"@1641826386.817524475","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Connection reset by peer","grpc_status":14}"
>
	{'API start': '2022-01-10 14:52:58.287537', 'RPC start': '2022-01-10 14:52:58.287552', 'RPC error': '2022-01-10 14:53:06.821180'} (pymilvus.client.grpc_handler:86)
[2022-01-10 14:54:09,609] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641826449.608479755","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 14:53:09.607981', 'RPC start': '2022-01-10 14:53:09.607988', 'RPC error': '2022-01-10 14:54:09.608981'} (pymilvus.client.grpc_handler:86)
[2022-01-10 14:54:09,610] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641826449.608479755","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 14:53:06.818680', 'RPC start': '2022-01-10 14:53:06.818696', 'RPC error': '2022-01-10 14:54:09.610074'} (pymilvus.client.grpc_handler:86)
[2022-01-10 14:55:09,615] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641826509.615379585","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 14:54:09.614475', 'RPC start': '2022-01-10 14:54:09.614482', 'RPC error': '2022-01-10 14:55:09.615809'} (pymilvus.client.grpc_handler:86)
[2022-01-10 14:55:09,616] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641826509.615379585","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 14:54:09.611156', 'RPC start': '2022-01-10 14:54:09.611164', 'RPC error': '2022-01-10 14:55:09.616766'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:00:09,621] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641826809.620451287","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 14:55:09.617619', 'RPC start': '2022-01-10 14:55:09.617626', 'RPC error': '2022-01-10 15:00:09.621177'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:00:09,625] [   DEBUG] - Ramping to {"MyUser": 4} (4 total users) (locust.runners:326)
[2022-01-10 15:00:09,627] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 2} already running)... (locust.runners:202)
[2022-01-10 15:00:09,628] [   DEBUG] - 4 users spawned (locust.runners:212)
[2022-01-10 15:00:09,628] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-10 15:00:09,629] [   DEBUG] - 0 users have been stopped, 4 still running (locust.runners:271)
[2022-01-10 15:00:09,631] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-10 15:00:09,632] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-10 15:00:09,633] [    INFO] -  grpc load_collection                                                                   1     0(0.00%)  |      10      10      10      10  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:00:09,633] [    INFO] -  grpc query                                                                             2   2(100.00%)  |   61398   60006   62791   60006  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:00:09,633] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-10 15:00:09,634] [    INFO] -  Aggregated                                                                             3    2(66.67%)  |   40935      10   62791   60000  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-10 15:00:09,634] [    INFO] -  (locust.stats_logger:733)
[2022-01-10 15:00:09,635] [   DEBUG] - [scene_test] Start scene test : scene_test_6951_749050 (milvus_benchmark.client:511)
[2022-01-10 15:00:09,728] [    INFO] - Create collection: <scene_test_6951_749050> successfully (milvus_benchmark.client:149)
[2022-01-10 15:00:09,729] [   DEBUG] - Milvus create_collection run in 0.0162s (milvus_benchmark.client:53)
[2022-01-10 15:05:09,729] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827109.728426148","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:00:09.635047', 'RPC start': '2022-01-10 15:00:09.635058', 'RPC error': '2022-01-10 15:05:09.729411'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:05:09,733] [   DEBUG] - Ramping to {"MyUser": 6} (6 total users) (locust.runners:326)
[2022-01-10 15:05:09,733] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 4} already running)... (locust.runners:202)
[2022-01-10 15:05:09,733] [   DEBUG] - 6 users spawned (locust.runners:212)
[2022-01-10 15:05:09,734] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-10 15:05:09,734] [   DEBUG] - 0 users have been stopped, 6 still running (locust.runners:271)
[2022-01-10 15:05:09,737] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-10 15:05:09,737] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-10 15:05:09,738] [    INFO] -  grpc load_collection                                                                   1     0(0.00%)  |      10      10      10      10  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:05:09,739] [    INFO] -  grpc query                                                                             2   2(100.00%)  |   61398   60006   62791   60006  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:05:09,739] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-10 15:05:09,740] [    INFO] -  Aggregated                                                                             3    2(66.67%)  |   40935      10   62791   60000  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-10 15:05:09,740] [    INFO] -  (locust.stats_logger:733)
[2022-01-10 15:05:09,758] [   DEBUG] - Milvus get_info run in 0.0222s (milvus_benchmark.client:53)
[2022-01-10 15:05:09,759] [   DEBUG] - [scene_test] Start insert : scene_test_6951_749050 (milvus_benchmark.client:518)
[2022-01-10 15:05:09,763] [   DEBUG] - Milvus load_collection run in 0.018s (milvus_benchmark.client:53)
[2022-01-10 15:06:09,765] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827169.763333677","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:05:09.762988', 'RPC start': '2022-01-10 15:05:09.762997', 'RPC error': '2022-01-10 15:06:09.765536'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:06:09,766] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827169.763333677","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:05:09.735646', 'RPC start': '2022-01-10 15:05:09.735654', 'RPC error': '2022-01-10 15:06:09.766280'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:06:09,798] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827169.765336615","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:05:09.764980', 'RPC start': '2022-01-10 15:05:09.764986', 'RPC error': '2022-01-10 15:06:09.798380'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:06:09,799] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827169.765336615","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:05:09.747446', 'RPC start': '2022-01-10 15:05:09.747454', 'RPC error': '2022-01-10 15:06:09.799001'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:06:09,840] [   DEBUG] - Milvus insert run in 60.0811s (milvus_benchmark.client:53)
[2022-01-10 15:06:09,841] [   DEBUG] - [scene_test] Start flush : scene_test_6951_749050 (milvus_benchmark.client:520)
[2022-01-10 15:06:09,845] [   DEBUG] - Ramping to {"MyUser": 8} (8 total users) (locust.runners:326)
[2022-01-10 15:06:09,846] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 6} already running)... (locust.runners:202)
[2022-01-10 15:06:09,846] [   DEBUG] - 8 users spawned (locust.runners:212)
[2022-01-10 15:06:09,846] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-10 15:06:09,846] [   DEBUG] - 0 users have been stopped, 8 still running (locust.runners:271)
[2022-01-10 15:06:09,848] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-10 15:06:09,848] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-10 15:06:09,849] [    INFO] -  grpc load_collection                                                                   2     0(0.00%)  |      14      10      18      10  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:06:09,849] [    INFO] -  grpc query                                                                             4   4(100.00%)  |  243582   60006  791480   60006  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:06:09,849] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-10 15:06:09,850] [    INFO] -  Aggregated                                                                             6    4(66.67%)  |  162392      10  791480   60000  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-10 15:06:09,850] [    INFO] -  (locust.stats_logger:733)
[2022-01-10 15:11:09,853] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827469.843547952","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:06:09.799670', 'RPC start': '2022-01-10 15:06:09.799677', 'RPC error': '2022-01-10 15:11:09.853556'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:11:09,855] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827229.844414324","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:06:09.844158', 'RPC start': '2022-01-10 15:06:09.844165', 'RPC error': '2022-01-10 15:11:09.855684'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:11:09,856] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827229.844414324","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:06:09.764271', 'RPC start': '2022-01-10 15:06:09.764288', 'RPC error': '2022-01-10 15:11:09.856321'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:11:09,871] [   DEBUG] - Milvus flush run in 300.0302s (milvus_benchmark.client:53)
[2022-01-10 15:16:09,877] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827769.868409988","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:06:09.847735', 'RPC start': '2022-01-10 15:06:09.847742', 'RPC error': '2022-01-10 15:16:09.877640'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:16:09,879] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827529.871440661","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:11:09.870685', 'RPC start': '2022-01-10 15:11:09.870700', 'RPC error': '2022-01-10 15:16:09.879397'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:16:09,879] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827529.871440661","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:06:09.840258', 'RPC start': '2022-01-10 15:06:09.840265', 'RPC error': '2022-01-10 15:16:09.879879'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:16:09,880] [   DEBUG] - Row count: 3000 in collection: <scene_test_6951_749050> (milvus_benchmark.client:421)
[2022-01-10 15:16:09,881] [   DEBUG] - [scene_test] Start create index : scene_test_6951_749050 (milvus_benchmark.client:525)
[2022-01-10 15:16:09,881] [    INFO] - Building index start, collection_name: scene_test_6951_749050, index_type: IVF_SQ8, metric_type: L2 (milvus_benchmark.client:274)
[2022-01-10 15:16:09,882] [    INFO] - {'nlist': 2048} (milvus_benchmark.client:276)
[2022-01-10 15:16:09,882] [   DEBUG] - collection: scene_test_6951_749050 Index params: {'index_type': 'IVF_SQ8', 'metric_type': 'L2', 'params': {'nlist': 2048}} (milvus_benchmark.client:282)
[2022-01-10 15:16:09,884] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827769.877346370","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:11:09.851835', 'RPC start': '2022-01-10 15:11:09.851847', 'RPC error': '2022-01-10 15:16:09.884756'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:16:09,887] [   DEBUG] - Ramping to {"MyUser": 10} (10 total users) (locust.runners:326)
[2022-01-10 15:16:09,888] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 8} already running)... (locust.runners:202)
[2022-01-10 15:16:09,888] [   DEBUG] - 10 users spawned (locust.runners:212)
[2022-01-10 15:16:09,889] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-10 15:16:09,889] [   DEBUG] - 0 users have been stopped, 10 still running (locust.runners:271)
[2022-01-10 15:16:09,890] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-10 15:16:09,890] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-10 15:16:09,891] [    INFO] -  grpc load_collection                                                                   2     0(0.00%)  |      14      10      18      10  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:16:09,891] [    INFO] -  grpc query                                                                             6   6(100.00%)  |  312410   60006  791480   63000  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-10 15:16:09,891] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-10 15:16:09,892] [    INFO] -  Aggregated                                                                             8    6(75.00%)  |  234311      10  791480   60000  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-10 15:16:09,892] [    INFO] -  (locust.stats_logger:733)
[2022-01-10 15:17:09,889] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827829.885399261","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:16:09.884427', 'RPC start': '2022-01-10 15:16:09.884434', 'RPC error': '2022-01-10 15:17:09.889932'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:17:09,891] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827829.885399261","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:11:09.849778', 'RPC start': '2022-01-10 15:11:09.849792', 'RPC error': '2022-01-10 15:17:09.891271'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:22:09,893] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827889.888467907","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:17:09.887361', 'RPC start': '2022-01-10 15:17:09.887367', 'RPC error': '2022-01-10 15:22:09.893515'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:22:09,894] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641827889.888467907","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:11:09.875371', 'RPC start': '2022-01-10 15:11:09.875380', 'RPC error': '2022-01-10 15:22:09.894861'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:23:09,897] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641828129.892424356","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:16:09.885851', 'RPC start': '2022-01-10 15:16:09.885858', 'RPC error': '2022-01-10 15:23:09.897145'} (pymilvus.client.grpc_handler:86)
[2022-01-10 15:23:09,901] [   ERROR] - 
Addr [benchmark-no-clean-kxmp4-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641828189.896465009","description":"Error received from peer ipv4:10.96.246.9:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-10 15:16:09.894654', 'RPC start': '2022-01-10 15:16:09.894661', 'RPC error': '2022-01-10 15:23:09.901917'} (pymilvus.client.grpc_handler:86)

@xige-16
Copy link
Contributor

xige-16 commented Jan 11, 2022

benchmark-no-clean-kxmp4-1-milvus-standalone-9fdc7b6dc-7qbp2

standalone restart, but querynode recovery failed. rootCoord set state to helthy before registe session to etcd, so when getRecoveryInfo call rootCoord's describeCollection, rootCoord return error after two retries.

[2022/01/10 14:53:51.242 +00:00] [DEBUG] [cluster.go:617] ["stopNode: queryNode offline"] [nodeID=4]
[2022/01/10 14:53:51.243 +00:00] [DEBUG] [task_scheduler.go:466] ["EnQueue a triggerTask and save to etcd"] [taskID=430394936994824193]
[2022/01/10 14:53:51.242 +00:00] [DEBUG] [session_util.go:379] ["watch services"] ["delete kv"="key:\"by-dev/meta/session/querynode-4\" create_revision:15 mod_revision:15 version:1 value:\"{\\\"ServerID\\\":4,\\\"ServerName\\\":\\\"querynode\\\",\\\"Address\\\":\\\"10.97.16.218:21123\\\",\\\"TriggerKill\\\":true}\" lease:6232557765448952156 "]
[2022/01/10 14:53:51.242 +00:00] [DEBUG] [session_util.go:388] [WatchService] ["event type"=2]
[2022/01/10 14:53:51.242 +00:00] [DEBUG] [query_coord.go:368] ["get a del event after QueryNode down"] [nodeID=4]
[2022/01/10 14:53:51.243 +00:00] [DEBUG] [task_scheduler.go:624] ["scheduleLoop: pop a triggerTask from triggerTaskQueue"] [triggerTaskID=430394936994824193]
[2022/01/10 14:53:51.243 +00:00] [DEBUG] [query_coord.go:398] ["start a loadBalance task"] [task="base:<msg_type:LoadBalanceSegments sourceID:14 > source_nodeIDs:4 balance_reason:NodeDown "]
[2022/01/10 14:53:51.243 +00:00] [DEBUG] [task.go:1650] ["start do loadBalanceTask"] ["trigger type"=4] [sourceNodeIDs="[4]"] [balanceReason=NodeDown] [taskID=430394936994824193]
[2022/01/10 14:53:51.244 +00:00] [DEBUG] [root_coord.go:1551] [ShowPartitions] [role=rootcoord] ["collection name"=] [msgID=0]
[2022/01/10 14:53:51.244 +00:00] [DEBUG] [task.go:1710] ["loadBalanceTask: get collection's all partitionIDs"] [collectionID=430393496637476161] [partitionIDs="[430393496637476162]"]
[2022/01/10 14:53:51.244 +00:00] [DEBUG] [root_coord.go:1569] ["ShowPartitions success"] [role=rootcoord] ["collection name"=] ["num of partitions"=1] [msgID=0]
[2022/01/10 14:53:51.245 +00:00] [INFO] [services.go:487] ["receive get recovery info request"] [collectionID=430393496637476161] [partitionID=430393496637476162]
[2022/01/10 14:53:51.247 +00:00] [DEBUG] [client.go:94] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2022/01/10 14:53:51.247 +00:00] [DEBUG] [client.go:94] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2022/01/10 14:53:51.247 +00:00] [ERROR] [client.go:131] ["failed to get client address"] [error="number of RootCoord is incorrect, 0"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).connect\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:131\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).GetGrpcClient\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:103\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).callOnce\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:193\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:239\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/10 14:53:51.247 +00:00] [WARN] [client.go:245] ["rootcoord ClientBase ReCall grpc first call get error "] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:244 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"]
[2022/01/10 14:53:51.247 +00:00] [DEBUG] [client.go:91] ["RootCoordClient GetSessions success"]
[2022/01/10 14:53:51.247 +00:00] [ERROR] [client.go:131] ["failed to get client address"] [error="number of RootCoord is incorrect, 0"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).connect\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:131\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).GetGrpcClient\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:103\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).callOnce\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:193\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:251\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/10 14:53:51.247 +00:00] [DEBUG] [client.go:91] ["RootCoordClient GetSessions success"]
[2022/01/10 14:53:51.248 +00:00] [DEBUG] [cluster.go:606] ["removeNodeInfo: delete nodeInfo in cluster MetaReplica"] [nodeID=4]
[2022/01/10 14:53:51.248 +00:00] [DEBUG] [task.go:1975] ["loadBalanceTask postExecute done"] ["trigger type"=4] [sourceNodeIDs="[4]"] [balanceReason=NodeDown] [taskID=430394936994824193]
[2022/01/10 14:53:51.248 +00:00] [DEBUG] [task_scheduler.go:629] ["scheduleLoop: process triggerTask failed"] [triggerTaskID=430394936994824193] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"]
[2022/01/10 14:53:51.248 +00:00] [ERROR] [services.go:582] ["get collection info from master failed"] [collectionID=430393496637476161] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"] [stack="github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:582\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/10 14:53:51.247 +00:00] [ERROR] [client.go:254] ["rootcoord ClientBase ReCall grpc second call get error "] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:254\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/10 14:53:51.248 +00:00] [ERROR] [task.go:1715] ["loadBalanceTask: getRecoveryInfo failed"] [collectionID=430393496637476161] [partitionID=430393496637476162] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"] [stack="github.com/milvus-io/milvus/internal/querycoord.(*loadBalanceTask).execute\n\t/go/src/github.com/milvus-io/milvus/internal/querycoord/task.go:1715\ngithub.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).processTask\n\t/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:550\ngithub.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).scheduleLoop\n\t/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:627"]
[2022/01/10 14:53:51.249 +00:00] [DEBUG] [task_scheduler.go:686] ["scheduleLoop: trigger task done and delete from etcd"] [triggerTaskID=430394936994824193]
[2022/01/10 14:53:51.630 +00:00] [DEBUG] [session_util.go:236] ["Session register successfully"] [ServerID=9]
[2022/01/10 14:53:51.631 +00:00] [DEBUG] [service.go:146] ["RootCoord start done ..."]

@wangting0128
Copy link
Contributor Author

argo task: benchmark-tag-sk47h

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m

server:

NAME                                                         READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-sk47h-1-etcd-0                                 1/1     Running     0          14h    10.97.17.229   qa-node014.zilliz.local   <none>           <none>
benchmark-tag-sk47h-1-milvus-standalone-8658c5dfbb-sv5t4     1/1     Running     2          14h    10.97.20.106   qa-node018.zilliz.local   <none>           <none>
benchmark-tag-sk47h-1-minio-5f8dd45bfb-m2sst                 1/1     Running     0          14h    10.97.12.70    qa-node015.zilliz.local   <none>           <none>

client pod: benchmark-tag-sk47h-2692756289

locust_report_2022-01-12_149.log

client log:

[2022-01-12 13:56:49,574] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995809.572083454","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:41.657780', 'RPC start': '2022-01-12 13:56:41.657793', 'RPC error': '2022-01-12 13:56:49.573819'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:56:49,575] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995809.572083454","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:41.650706', 'RPC start': '2022-01-12 13:56:41.650720', 'RPC error': '2022-01-12 13:56:49.574947'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:56:49,576] [   DEBUG] - Ramping to {"MyUser": 4} (4 total users) (locust.runners:326)
[2022-01-12 13:56:49,577] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 2} already running)... (locust.runners:202)
[2022-01-12 13:56:49,577] [   DEBUG] - 4 users spawned (locust.runners:212)
[2022-01-12 13:56:49,578] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-12 13:56:49,578] [   DEBUG] - 0 users have been stopped, 4 still running (locust.runners:271)
[2022-01-12 13:56:49,581] [   DEBUG] - [scene_test] Start scene test : scene_test_435_899983 (milvus_benchmark.client:511)
[2022-01-12 13:57:04,196] [   DEBUG] - Milvus get_info run in 14.6168s (milvus_benchmark.client:53)
[2022-01-12 13:57:04,197] [   DEBUG] - [scene_test] Start insert : scene_test_8323_36719 (milvus_benchmark.client:518)
[2022-01-12 13:57:04,199] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] create_collection
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "failed to connect to all addresses"
	debug_error_string = "{"created":"@1641995814.822010768","description":"Failed to pick subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":5420,"referenced_errors":[{"created":"@1641995814.822003152","description":"failed to connect to all addresses","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":398,"grpc_status":14}]}"
>
	{'API start': '2022-01-12 13:56:49.582574', 'RPC start': '2022-01-12 13:56:49.582592', 'RPC error': '2022-01-12 13:57:04.199222'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:57:33,275] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995853.273137046","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:49.584722', 'RPC start': '2022-01-12 13:56:49.584734', 'RPC error': '2022-01-12 13:57:33.275641'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:57:48,350] [   DEBUG] - Milvus insert run in 44.1523s (milvus_benchmark.client:53)
[2022-01-12 13:57:48,351] [   DEBUG] - [scene_test] Start flush : scene_test_8323_36719 (milvus_benchmark.client:520)
[2022-01-12 13:57:48,358] [   DEBUG] - Ramping to {"MyUser": 6} (6 total users) (locust.runners:326)
[2022-01-12 13:57:48,359] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 4} already running)... (locust.runners:202)
[2022-01-12 13:57:48,359] [   DEBUG] - 6 users spawned (locust.runners:212)
[2022-01-12 13:57:48,360] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-12 13:57:48,360] [   DEBUG] - 0 users have been stopped, 6 still running (locust.runners:271)
[2022-01-12 13:57:48,361] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-12 13:57:48,362] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-12 13:57:48,362] [    INFO] -  grpc get                                                                               3     0(0.00%)  |    2238    1161    2778    2778  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-12 13:57:48,363] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-12 13:57:48,364] [    INFO] -  Aggregated                                                                             3     0(0.00%)  |    2238    1161    2778    2778  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-12 13:57:48,364] [    INFO] -  (locust.stats_logger:733)
[2022-01-12 14:02:48,395] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641996168.393573095","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-12 13:57:48.378736', 'RPC start': '2022-01-12 13:57:48.378755', 'RPC error': '2022-01-12 14:02:48.394902'} (pymilvus.client.grpc_handler:86)
[2022-01-12 14:02:48,396] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641996168.394517043","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-12 13:57:48.380469', 'RPC start': '2022-01-12 13:57:48.380478', 'RPC error': '2022-01-12 14:02:48.396892'} (pymilvus.client.grpc_handler:86)
[2022-01-12 14:02:48,398] [   DEBUG] - Ramping to {"MyUser": 8} (8 total users) (locust.runners:326)

@xige-16
Copy link
Contributor

xige-16 commented Jan 13, 2022

argo task: benchmark-tag-sk47h

test yaml: client-configmap:client-random-locust-100m-ddl-r8-w2 server-configmap:server-single-32c128m

server:

NAME                                                         READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-sk47h-1-etcd-0                                 1/1     Running     0          14h    10.97.17.229   qa-node014.zilliz.local   <none>           <none>
benchmark-tag-sk47h-1-milvus-standalone-8658c5dfbb-sv5t4     1/1     Running     2          14h    10.97.20.106   qa-node018.zilliz.local   <none>           <none>
benchmark-tag-sk47h-1-minio-5f8dd45bfb-m2sst                 1/1     Running     0          14h    10.97.12.70    qa-node015.zilliz.local   <none>           <none>

client pod: benchmark-tag-sk47h-2692756289

locust_report_2022-01-12_149.log

client log:

[2022-01-12 13:56:49,574] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995809.572083454","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:41.657780', 'RPC start': '2022-01-12 13:56:41.657793', 'RPC error': '2022-01-12 13:56:49.573819'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:56:49,575] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995809.572083454","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:41.650706', 'RPC start': '2022-01-12 13:56:41.650720', 'RPC error': '2022-01-12 13:56:49.574947'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:56:49,576] [   DEBUG] - Ramping to {"MyUser": 4} (4 total users) (locust.runners:326)
[2022-01-12 13:56:49,577] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 2} already running)... (locust.runners:202)
[2022-01-12 13:56:49,577] [   DEBUG] - 4 users spawned (locust.runners:212)
[2022-01-12 13:56:49,578] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-12 13:56:49,578] [   DEBUG] - 0 users have been stopped, 4 still running (locust.runners:271)
[2022-01-12 13:56:49,581] [   DEBUG] - [scene_test] Start scene test : scene_test_435_899983 (milvus_benchmark.client:511)
[2022-01-12 13:57:04,196] [   DEBUG] - Milvus get_info run in 14.6168s (milvus_benchmark.client:53)
[2022-01-12 13:57:04,197] [   DEBUG] - [scene_test] Start insert : scene_test_8323_36719 (milvus_benchmark.client:518)
[2022-01-12 13:57:04,199] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] create_collection
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "failed to connect to all addresses"
	debug_error_string = "{"created":"@1641995814.822010768","description":"Failed to pick subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":5420,"referenced_errors":[{"created":"@1641995814.822003152","description":"failed to connect to all addresses","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":398,"grpc_status":14}]}"
>
	{'API start': '2022-01-12 13:56:49.582574', 'RPC start': '2022-01-12 13:56:49.582592', 'RPC error': '2022-01-12 13:57:04.199222'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:57:33,275] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995853.273137046","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:49.584722', 'RPC start': '2022-01-12 13:56:49.584734', 'RPC error': '2022-01-12 13:57:33.275641'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:57:48,350] [   DEBUG] - Milvus insert run in 44.1523s (milvus_benchmark.client:53)
[2022-01-12 13:57:48,351] [   DEBUG] - [scene_test] Start flush : scene_test_8323_36719 (milvus_benchmark.client:520)
[2022-01-12 13:57:48,358] [   DEBUG] - Ramping to {"MyUser": 6} (6 total users) (locust.runners:326)
[2022-01-12 13:57:48,359] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 4} already running)... (locust.runners:202)
[2022-01-12 13:57:48,359] [   DEBUG] - 6 users spawned (locust.runners:212)
[2022-01-12 13:57:48,360] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-12 13:57:48,360] [   DEBUG] - 0 users have been stopped, 6 still running (locust.runners:271)
[2022-01-12 13:57:48,361] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-12 13:57:48,362] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-12 13:57:48,362] [    INFO] -  grpc get                                                                               3     0(0.00%)  |    2238    1161    2778    2778  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-12 13:57:48,363] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-12 13:57:48,364] [    INFO] -  Aggregated                                                                             3     0(0.00%)  |    2238    1161    2778    2778  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-12 13:57:48,364] [    INFO] -  (locust.stats_logger:733)
[2022-01-12 14:02:48,395] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641996168.393573095","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-12 13:57:48.378736', 'RPC start': '2022-01-12 13:57:48.378755', 'RPC error': '2022-01-12 14:02:48.394902'} (pymilvus.client.grpc_handler:86)
[2022-01-12 14:02:48,396] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641996168.394517043","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-12 13:57:48.380469', 'RPC start': '2022-01-12 13:57:48.380478', 'RPC error': '2022-01-12 14:02:48.396892'} (pymilvus.client.grpc_handler:86)
[2022-01-12 14:02:48,398] [   DEBUG] - Ramping to {"MyUser": 8} (8 total users) (locust.runners:326)

search-panic.log
@bigsheeper

@xige-16
Copy link
Contributor

xige-16 commented Jan 13, 2022

argo task: benchmark-tag-sk47h

test yaml: client-configmap:client-random-locust-100m-ddl-r8-w2 server-configmap:server-single-32c128m

server:

NAME                                                         READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-sk47h-1-etcd-0                                 1/1     Running     0          14h    10.97.17.229   qa-node014.zilliz.local   <none>           <none>
benchmark-tag-sk47h-1-milvus-standalone-8658c5dfbb-sv5t4     1/1     Running     2          14h    10.97.20.106   qa-node018.zilliz.local   <none>           <none>
benchmark-tag-sk47h-1-minio-5f8dd45bfb-m2sst                 1/1     Running     0          14h    10.97.12.70    qa-node015.zilliz.local   <none>           <none>

client pod: benchmark-tag-sk47h-2692756289

locust_report_2022-01-12_149.log

client log:

[2022-01-12 13:56:49,574] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] _execute_search_requests
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995809.572083454","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:41.657780', 'RPC start': '2022-01-12 13:56:41.657793', 'RPC error': '2022-01-12 13:56:49.573819'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:56:49,575] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] search
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995809.572083454","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:41.650706', 'RPC start': '2022-01-12 13:56:41.650720', 'RPC error': '2022-01-12 13:56:49.574947'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:56:49,576] [   DEBUG] - Ramping to {"MyUser": 4} (4 total users) (locust.runners:326)
[2022-01-12 13:56:49,577] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 2} already running)... (locust.runners:202)
[2022-01-12 13:56:49,577] [   DEBUG] - 4 users spawned (locust.runners:212)
[2022-01-12 13:56:49,578] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-12 13:56:49,578] [   DEBUG] - 0 users have been stopped, 4 still running (locust.runners:271)
[2022-01-12 13:56:49,581] [   DEBUG] - [scene_test] Start scene test : scene_test_435_899983 (milvus_benchmark.client:511)
[2022-01-12 13:57:04,196] [   DEBUG] - Milvus get_info run in 14.6168s (milvus_benchmark.client:53)
[2022-01-12 13:57:04,197] [   DEBUG] - [scene_test] Start insert : scene_test_8323_36719 (milvus_benchmark.client:518)
[2022-01-12 13:57:04,199] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] create_collection
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "failed to connect to all addresses"
	debug_error_string = "{"created":"@1641995814.822010768","description":"Failed to pick subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":5420,"referenced_errors":[{"created":"@1641995814.822003152","description":"failed to connect to all addresses","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":398,"grpc_status":14}]}"
>
	{'API start': '2022-01-12 13:56:49.582574', 'RPC start': '2022-01-12 13:56:49.582592', 'RPC error': '2022-01-12 13:57:04.199222'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:57:33,275] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.UNAVAILABLE
	details = "Socket closed"
	debug_error_string = "{"created":"@1641995853.273137046","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Socket closed","grpc_status":14}"
>
	{'API start': '2022-01-12 13:56:49.584722', 'RPC start': '2022-01-12 13:56:49.584734', 'RPC error': '2022-01-12 13:57:33.275641'} (pymilvus.client.grpc_handler:86)
[2022-01-12 13:57:48,350] [   DEBUG] - Milvus insert run in 44.1523s (milvus_benchmark.client:53)
[2022-01-12 13:57:48,351] [   DEBUG] - [scene_test] Start flush : scene_test_8323_36719 (milvus_benchmark.client:520)
[2022-01-12 13:57:48,358] [   DEBUG] - Ramping to {"MyUser": 6} (6 total users) (locust.runners:326)
[2022-01-12 13:57:48,359] [   DEBUG] - Spawning additional {"MyUser": 2} ({"MyUser": 4} already running)... (locust.runners:202)
[2022-01-12 13:57:48,359] [   DEBUG] - 6 users spawned (locust.runners:212)
[2022-01-12 13:57:48,360] [   DEBUG] - All users of class MyUser spawned (locust.runners:213)
[2022-01-12 13:57:48,360] [   DEBUG] - 0 users have been stopped, 6 still running (locust.runners:271)
[2022-01-12 13:57:48,361] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-12 13:57:48,362] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-12 13:57:48,362] [    INFO] -  grpc get                                                                               3     0(0.00%)  |    2238    1161    2778    2778  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-12 13:57:48,363] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-12 13:57:48,364] [    INFO] -  Aggregated                                                                             3     0(0.00%)  |    2238    1161    2778    2778  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-12 13:57:48,364] [    INFO] -  (locust.stats_logger:733)
[2022-01-12 14:02:48,395] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641996168.393573095","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-12 13:57:48.378736', 'RPC start': '2022-01-12 13:57:48.378755', 'RPC error': '2022-01-12 14:02:48.394902'} (pymilvus.client.grpc_handler:86)
[2022-01-12 14:02:48,396] [   ERROR] - 
Addr [benchmark-tag-sk47h-1-milvus.qa-milvus.svc.cluster.local:19530] query
RPC error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1641996168.394517043","description":"Error received from peer ipv4:10.96.250.87:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
>
	{'API start': '2022-01-12 13:57:48.380469', 'RPC start': '2022-01-12 13:57:48.380478', 'RPC error': '2022-01-12 14:02:48.396892'} (pymilvus.client.grpc_handler:86)
[2022-01-12 14:02:48,398] [   DEBUG] - Ramping to {"MyUser": 8} (8 total users) (locust.runners:326)

Search panic, after standalone restart, querycoord cannot obtain recovery information through DataCoord.GetRecoveryInfo when recovering node load, resulting in standalone panic again, but querycoord clears the querynode information that needs to be recovered before panic, which is wrong

[2022/01/12 13:57:33.207 +00:00] [DEBUG] [task_scheduler.go:466] ["EnQueue a triggerTask and save to etcd"] [taskID=430439352507039745]
[2022/01/12 13:57:33.207 +00:00] [DEBUG] [query_coord.go:398] ["start a loadBalance task"] [task="base:<msg_type:LoadBalanceSegments sourceID:14 > source_nodeIDs:4 balance_reason:NodeDown "]
[2022/01/12 13:57:33.207 +00:00] [DEBUG] [task_scheduler.go:624] ["scheduleLoop: pop a triggerTask from triggerTaskQueue"] [triggerTaskID=430439352507039745]
[2022/01/12 13:57:33.207 +00:00] [DEBUG] [task.go:1633] ["start do loadBalanceTask"] ["trigger type"=4] [sourceNodeIDs="[4]"] [balanceReason=NodeDown] [taskID=430439352507039745]
[2022/01/12 13:57:33.208 +00:00] [DEBUG] [task.go:1684] ["loadBalanceTask: get collection's all partitionIDs"] [collectionID=430437415579225409] [partitionIDs="[430437415579225410]"]
[2022/01/12 13:57:33.208 +00:00] [DEBUG] [root_coord.go:1551] [ShowPartitions] [role=rootcoord] ["collection name"=] [msgID=0]
[2022/01/12 13:57:33.208 +00:00] [DEBUG] [root_coord.go:1569] ["ShowPartitions success"] [role=rootcoord] ["collection name"=] ["num of partitions"=1] [msgID=0]
[2022/01/12 13:57:33.208 +00:00] [INFO] [services.go:487] ["receive get recovery info request"] [collectionID=430437415579225409] [partitionID=430437415579225410]
[2022/01/12 13:57:33.210 +00:00] [DEBUG] [client.go:91] ["RootCoordClient GetSessions success"]
[2022/01/12 13:57:33.210 +00:00] [DEBUG] [client.go:94] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2022/01/12 13:57:33.210 +00:00] [ERROR] [client.go:131] ["failed to get client address"] [error="number of RootCoord is incorrect, 0"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).connect\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:131\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).GetGrpcClient\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:103\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).callOnce\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:193\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:239\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/12 13:57:33.210 +00:00] [DEBUG] [client.go:91] ["RootCoordClient GetSessions success"]
[2022/01/12 13:57:33.210 +00:00] [DEBUG] [client.go:94] ["RootCoordClient mess key not exist"] [key=rootcoord]
[2022/01/12 13:57:33.210 +00:00] [ERROR] [client.go:131] ["failed to get client address"] [error="number of RootCoord is incorrect, 0"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).connect\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:131\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).GetGrpcClient\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:103\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).callOnce\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:193\ngithub.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:251\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/12 13:57:33.210 +00:00] [ERROR] [client.go:254] ["rootcoord ClientBase ReCall grpc second call get error "] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"] [stack="github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n\t/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:254\ngithub.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201\ngithub.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/12 13:57:33.210 +00:00] [ERROR] [services.go:582] ["get collection info from master failed"] [collectionID=430437415579225409] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"] [stack="github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:582\ngithub.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n\t/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38\ngithub.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n\t/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1286\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1609\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:934"]
[2022/01/12 13:57:33.210 +00:00] [WARN] [client.go:245] ["rootcoord ClientBase ReCall grpc first call get error "] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:244 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"]
[2022/01/12 13:57:33.210 +00:00] [ERROR] [task.go:1689] ["loadBalanceTask: getRecoveryInfo failed"] [collectionID=430437415579225409] [partitionID=430437415579225410] [error="err: number of RootCoord is incorrect, 0\n, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace\n/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall\n/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection\n/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1\n/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC\n/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream\n"] [stack="github.com/milvus-io/milvus/internal/querycoord.(*loadBalanceTask).execute\n\t/go/src/github.com/milvus-io/milvus/internal/querycoord/task.go:1689\ngithub.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).processTask\n\t/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:550\ngithub.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).scheduleLoop\n\t/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:627"]
[2022/01/12 13:57:33.211 +00:00] [DEBUG] [task.go:1945] ["loadBalanceTask postExecute done"] ["trigger type"=4] [sourceNodeIDs="[4]"] [balanceReason=NodeDown] [taskID=430439352507039745]
[2022/01/12 13:57:33.211 +00:00] [DEBUG] [cluster.go:606] ["removeNodeInfo: delete nodeInfo in cluster MetaReplica"] [nodeID=4]
[2022/01/12 13:57:33.211 +00:00] [DEBUG] [cluster.go:606] ["removeNodeInfo: delete nodeInfo in cluster MetaReplica"] [nodeID=4]
panic: err: number of RootCoord is incorrect, 0
goroutine 706 [running]:
	/go/src/github.com/milvus-io/milvus/internal/querycoord/task.go:1690 +0x5bb2
/go/src/github.com/milvus-io/milvus/internal/distributed/rootcoord/client/client.go:201 github.com/milvus-io/milvus/internal/distributed/rootcoord/client.(*Client).DescribeCollection
/go/src/github.com/milvus-io/milvus/internal/distributed/datacoord/service.go:283 github.com/milvus-io/milvus/internal/distributed/datacoord.(*Server).GetRecoveryInfo
/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3898 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler.func1
/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tracing/opentracing/server_interceptors.go:38 github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1
/go/pkg/mod/google.golang.org/[email protected]/server.go:1286 google.golang.org/grpc.(*Server).processUnaryRPC
/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 google.golang.org/grpc.(*Server).handleStream
	/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:550 +0x6d4
	/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:627 +0x12bf
github.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).processTask(0xc001d68dc0, 0x35adaa0, 0xc003cbc180, 0x0, 0x0)
github.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).scheduleLoop(0xc001d68dc0)
created by github.com/milvus-io/milvus/internal/querycoord.(*TaskScheduler).Start
	/go/src/github.com/milvus-io/milvus/internal/querycoord/task_scheduler.go:868 +0x65
, /go/src/github.com/milvus-io/milvus/internal/util/trace/stack_trace.go:51 github.com/milvus-io/milvus/internal/util/trace.StackTrace
/go/src/github.com/milvus-io/milvus/internal/util/grpcclient/client.go:253 github.com/milvus-io/milvus/internal/util/grpcclient.(*ClientBase).ReCall
/go/src/github.com/milvus-io/milvus/internal/datacoord/services.go:574 github.com/milvus-io/milvus/internal/datacoord.(*Server).GetRecoveryInfo
/go/src/github.com/milvus-io/milvus/internal/proto/datapb/data_coord.pb.go:3900 github.com/milvus-io/milvus/internal/proto/datapb._DataCoord_GetRecoveryInfo_Handler

@bigsheeper
Copy link
Contributor

[TODO: remove] debug #14077, segment_id = 430437950405214210, SegmentSealedImpl::vector_search begin to search..., vec_count = 0xbd44c, query_count = 0xa, timestamp = 0xffffffffffffffff
[TODO: remove] debug #14077, segment_id = 430437950405214210, SegmentSealedImpl vector indexes is ready for field
[TODO: remove] debug #14077, segment_id = 430437950405214210, SegmentSealedImpl get field meta done
[TODO: remove] debug #14077, segment_id = 430437950405214210, SearchOnSealed init topk, round_decimal, field_offset, field and dim done
[TODO: remove] debug #14077, segment_id = 430437950405214210, SearchOnSealed get_field_indexing done
[TODO: remove] debug #14077, segment_id = 430437950405214210, SearchOnSealed GenDataset done
[TODO: remove] debug #14077, segment_id = 430437950405214210, SearchOnSealed get index_type done

Search panic after SearchOnSealed get index_type done, PTAL @cydrain

@cydrain
Copy link
Contributor

cydrain commented Jan 14, 2022

Have checked all code diff under directory "internal/core" between rc8 and latest, no findings.
Since this issue is introduced after rc8, I build a debug image with latest Milvus code + core of rc8.
This can tell whether this issue is caused by code change in core.

https://argo-test.milvus.io/workflow-templates/qa/benchmark

server-single-32c128m	client-random-locust-100m-ddl-r8-w2

@cydrain
Copy link
Contributor

cydrain commented Jan 15, 2022

#run1
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/18
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_rc8-20220114
https://argo-test.milvus.io/workflows/qa/benchmark-59tqm?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATE
D NODE   READINESS GATES
benchmark-59tqm-1-etcd-0                                          1/1     Running     0          87s    10.97.17.100   qa-node014.zilliz.local   <none>
         <none>
benchmark-59tqm-1-milvus-standalone-c84698b75-m4tfk               1/1     Running     0          87s    10.97.16.54    qa-node013.zilliz.local   <none>
         <none>
benchmark-59tqm-1-minio-7b4649c889-kpq6v                          1/1     Running     0          87s    10.97.19.106   qa-node016.zilliz.local   <none>
         <none>

#run2 (panic)
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/20
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_20211231-20220115
https://argo-test.milvus.io/workflows/qa/benchmark-dwxcl?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATE
D NODE   READINESS GATES
benchmark-dwxcl-1-etcd-0                                          1/1     Running     0          91s    10.97.17.102   qa-node014.zilliz.local   <none>
         <none>
benchmark-dwxcl-1-milvus-standalone-54cccfddc-24q8w               1/1     Running     0          91s    10.97.20.22    qa-node018.zilliz.local   <none>
         <none>
benchmark-dwxcl-1-minio-85658874d8-82tpm                          1/1     Running     0          91s    10.97.12.132   qa-node015.zilliz.local   <none>
         <none>

#run3 (panic)
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/21
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_20220104-20220115
https://argo-test.milvus.io/workflows/qa/benchmark-bhjnm?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE     IP             NODE                      NOMINAT
ED NODE   READINESS GATES
benchmark-bhjnm-1-etcd-0                                          1/1     Running     0          89s     10.97.17.108   qa-node014.zilliz.local   <none>
          <none>
benchmark-bhjnm-1-milvus-standalone-857d47cf6c-2jrkx              1/1     Running     0          89s     10.97.17.106   qa-node014.zilliz.local   <none>
          <none>
benchmark-bhjnm-1-minio-6cc8bbf5d4-wkscc                          1/1     Running     0          89s     10.97.12.163   qa-node015.zilliz.local   <none>
          <none>

#run4
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_rc8-20220114
https://argo-test.milvus.io/workflows/qa/benchmark-6v72l?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATE
D NODE   READINESS GATES
benchmark-6v72l-1-etcd-0                                          1/1     Running     0          93s    10.97.17.137   qa-node014.zilliz.local   <none>
         <none>
benchmark-6v72l-1-milvus-standalone-54678bf47b-shkt4              1/1     Running     0          93s    10.97.20.28    qa-node018.zilliz.local   <none>
         <none>
benchmark-6v72l-1-minio-57799f8c85-8p2v5                          1/1     Running     0          93s    10.97.12.170   qa-node015.zilliz.local   <none>
         <none>

@xiaofan-luan
Copy link
Collaborator

any progress?

@cydrain
Copy link
Contributor

cydrain commented Jan 15, 2022

any progress?

still running

@cydrain
Copy link
Contributor

cydrain commented Jan 16, 2022

#run5
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/22
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_20211130-20220116
https://argo-test.milvus.io/workflows/qa/benchmark-s75kb?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE     IP             NODE                      NOMINAT
ED NODE   READINESS GATES
benchmark-s75kb-1-etcd-0                                          1/1     Running     0          89s     10.97.17.140   qa-node014.zilliz.local   <none>
          <none>
benchmark-s75kb-1-milvus-standalone-6845d45b57-qzsnz              1/1     Running     0          89s     10.97.20.29    qa-node018.zilliz.local   <none>
          <none>
benchmark-s75kb-1-minio-689b8b57bc-5b2xm                          1/1     Running     0          89s     10.97.12.187   qa-node015.zilliz.local   <none>
          <none>

#run6
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/23
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_20211215-20220116
https://argo-test.milvus.io/workflows/qa/benchmark-l8m4j?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE     IP             NODE                      NOMINAT
ED NODE   READINESS GATES
benchmark-l8m4j-1-etcd-0                                          1/1     Running     0          97s     10.97.16.74    qa-node013.zilliz.local   <none>
          <none>
benchmark-l8m4j-1-milvus-standalone-65f6b796c-jsxtt               1/1     Running     0          97s     10.97.17.141   qa-node014.zilliz.local   <none>
          <none>
benchmark-l8m4j-1-minio-99fd945b5-rpkwd                           1/1     Running     0          97s     10.97.12.189   qa-node015.zilliz.local   <none>
          <none>

#run7
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/24
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_use_core_20211222-20220117
https://argo-test.milvus.io/workflows/qa/benchmark-hqkqp?tab=workflow

NAME                                                              READY   STATUS      RESTARTS   AGE     IP             NODE                      NOMINAT
ED NODE   READINESS GATES
benchmark-hqkqp-1-etcd-0                                          1/1     Running     0          95s     10.97.17.160   qa-node014.zilliz.local   <none>
          <none>
benchmark-hqkqp-1-milvus-standalone-68d9d4656b-b9bk8              1/1     Running     0          95s     10.97.20.30    qa-node018.zilliz.local   <none>
          <none>
benchmark-hqkqp-1-minio-67f4db6776-sm7tj                          1/1     Running     0          95s     10.97.19.142   qa-node016.zilliz.local   <none>
          <none>

@wangting0128
Copy link
Contributor Author

argo task: benchmark-tag-s7642

test yaml:
client-configmap:client-random-locust-100m-ddl-r8-w2
server-configmap:server-single-32c128m

server:

NAME                                                              READY   STATUS      RESTARTS   AGE    IP             NODE                      NOMINATED NODE   READINESS GATES
benchmark-tag-s7642-1-etcd-0                                      1/1     Running     0          46h    10.97.17.85    qa-node014.zilliz.local   <none>           <none>
benchmark-tag-s7642-1-milvus-standalone-6989f48dcf-t5z44          1/1     Running     0          46h    10.97.16.31    qa-node013.zilliz.local   <none>           <none>
benchmark-tag-s7642-1-minio-5b7859ccb-qphhd                       1/1     Running     0          46h    10.97.19.63    qa-node016.zilliz.local   <none>           <none>

client pod: benchmark-tag-s7642-4095128662

client log:

[2022-01-15 22:34:30,112] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642285830.106778223","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:34:30,113] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642285830.106778223","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:34:30,114] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642285830.107693386","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:34:30,114] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642285830.107693386","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:34:30,114] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286070.108787030","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:38:49,004] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286130.117720370","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:38:49,005] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286130.117720370","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:38:49,006] [   DEBUG] - Milvus get run in 558.9086s (milvus_benchmark.client:53)
[2022-01-15 22:43:07,239] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286329.007926799","description":"Deadline Exceeded","file":"src/core/ext/filters/deadline/deadline_filter.cc","file_line":81,"grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:43:07,242] [   DEBUG] - Milvus get run in 517.1273s (milvus_benchmark.client:53)
[2022-01-15 22:43:07,250] [   DEBUG] - [scene_test] Start drop : scene_test_1423_592153 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,251] [    INFO] - Start Drop collection: scene_test_1423_592153 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,256] [   DEBUG] - [scene_test] Start drop : scene_test_7478_579814 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,256] [    INFO] - Start Drop collection: scene_test_7478_579814 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,257] [   DEBUG] - [scene_test] Start drop : scene_test_2897_957049 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,257] [    INFO] - Start Drop collection: scene_test_2897_957049 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,258] [   DEBUG] - [scene_test] Start drop : scene_test_2573_478983 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,259] [    INFO] - Start Drop collection: scene_test_2573_478983 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,259] [   DEBUG] - [scene_test] Start drop : scene_test_3771_857818 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,260] [    INFO] - Start Drop collection: scene_test_3771_857818 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,262] [    INFO] -  Name                                                                              # reqs      # fails  |     Avg     Min     Max  Median  |   req/s failures/s (locust.stats_logger:725)
[2022-01-15 22:43:07,262] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:727)
[2022-01-15 22:43:07,263] [    INFO] -  grpc get                                                                           40162     0(0.00%)  |    2856     786  558908    2500  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-15 22:43:07,264] [    INFO] -  grpc load_collection                                                                4972     0(0.00%)  |    1918       2   12047    1600  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-15 22:43:07,264] [    INFO] -  grpc query                                                                         40346     3(0.01%)  |    2868      72  558907    2600  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-15 22:43:07,265] [    INFO] -  grpc scene_test                                                                     9895     0(0.00%)  |   82762   63841  395054   83000  |    0.00    0.00 (locust.stats_logger:730)
[2022-01-15 22:43:07,266] [    INFO] - ---------------------------------------------------------------------------------------------------------------------------------------------------------------- (locust.stats_logger:731)
[2022-01-15 22:43:07,267] [    INFO] -  Aggregated                                                                         95375     3(0.00%)  |   11102       2  558908    2800  |    0.00    0.00 (locust.stats_logger:732)
[2022-01-15 22:43:07,268] [    INFO] -  (locust.stats_logger:733)
[2022-01-15 22:43:07,269] [   DEBUG] - [scene_test] Start drop : scene_test_7112_539508 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,269] [    INFO] - Start Drop collection: scene_test_7112_539508 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,270] [   DEBUG] - [scene_test] Start drop : scene_test_5019_940310 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,271] [    INFO] - Start Drop collection: scene_test_5019_940310 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,271] [   DEBUG] - [scene_test] Start drop : scene_test_6591_368693 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,272] [    INFO] - Start Drop collection: scene_test_6591_368693 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,274] [   DEBUG] - [scene_test] Start drop : scene_test_2528_856379 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,275] [    INFO] - Start Drop collection: scene_test_2528_856379 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,277] [   DEBUG] - [scene_test] Start drop : scene_test_154_613193 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,278] [    INFO] - Start Drop collection: scene_test_154_613193 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,278] [   DEBUG] - [scene_test] Start drop : scene_test_2604_511469 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,280] [    INFO] - Start Drop collection: scene_test_2604_511469 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,281] [   DEBUG] - [scene_test] Start drop : scene_test_4134_162441 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,282] [    INFO] - Start Drop collection: scene_test_4134_162441 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,283] [   DEBUG] - [scene_test] Start drop : scene_test_3165_455387 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,284] [    INFO] - Start Drop collection: scene_test_3165_455387 (milvus_benchmark.client:429)
[2022-01-15 22:43:07,284] [   DEBUG] - [scene_test] Start drop : scene_test_6692_520247 (milvus_benchmark.client:530)
[2022-01-15 22:43:07,285] [    INFO] - Start Drop collection: scene_test_6692_520247 (milvus_benchmark.client:429)
[2022-01-15 22:47:29,914] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286647.248712004","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:47:29,915] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286647.248712004","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:47:29,915] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286647.249685730","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:47:29,916] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286647.249685730","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:47:29,916] [   DEBUG] - Milvus get run in 520.9093s (milvus_benchmark.client:53)
[2022-01-15 22:48:29,915] [   DEBUG] - Drop collection scene_test_1423_592153 done. (milvus_benchmark.client:447)
[2022-01-15 22:48:29,916] [   DEBUG] - Milvus drop run in 322.665s (milvus_benchmark.client:53)
[2022-01-15 22:48:29,916] [   DEBUG] - [scene_test]Scene test close : scene_test_1423_592153 (milvus_benchmark.client:532)
[2022-01-15 22:48:29,917] [   DEBUG] - Milvus scene_test run in 1214.5675s (milvus_benchmark.client:53)
[2022-01-15 22:48:29,919] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286909.914844780","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)
[2022-01-15 22:48:29,919] [   ERROR] - Error: <_MultiThreadedRendezvous of RPC that terminated with:
	status = StatusCode.DEADLINE_EXCEEDED
	details = "Deadline Exceeded"
	debug_error_string = "{"created":"@1642286909.914844780","description":"Error received from peer ipv4:10.96.38.128:19530","file":"src/core/lib/surface/call.cc","file_line":1068,"grpc_message":"Deadline Exceeded","grpc_status":4}"
> (pymilvus.decorators:75)

@cydrain
Copy link
Contributor

cydrain commented Jan 17, 2022

run code result
1 2022/01/11 base code + rc8 core ok
2 2022/01/11 base code + 2021/11/30 core ok
3 2022/01/11 base code + 2021/12/15 core ok
4 2022/01/11 base code + 2021/12/22 core panic
5 2022/01/11 base code + 2021/12/31 core panic
6 2022/01/11 base code + 2022/01/04 core panic

run argo 6 times, the root cause of this issue MUST in the code change of "core" between 2021/12/15 ~ 2021/12/22

@bigsheeper
Copy link
Contributor

run code result
1 2022/01/11 base code + rc8 core ok
2 2022/01/11 base code + 2021/11/30 core ok
3 2022/01/11 base code + 2021/12/15 core ok
4 2022/01/11 base code + 2021/12/22 core panic
5 2022/01/11 base code + 2021/12/31 core panic
6 2022/01/11 base code + 2022/01/04 core panic
run argo 6 times, the root cause of this issue MUST in the code change of "core" between 2021/12/15 ~ 2021/12/22

code change of "core" between 2021/12/15 ~ 2021/12/22:
bigsheeper/milvus@2202-tag-20211215...bigsheeper:2202-tag-20211215-with-22-core

@cydrain
Copy link
Contributor

cydrain commented Jan 21, 2022

Compared the code diff between 2021/11/30 ~ 2021/12/31, find no suspicious PR which could cause Search panic.
Plan:

  1. re-test 2021/11/30 and 2021/12/15 docker images
  2. find a way to let Cgo print out backtrace info or coredump

@cydrain
Copy link
Contributor

cydrain commented Jan 21, 2022

Have build docker image supporting coredump
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/38/pipeline
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_20211231_support_coredump-473181250-20220127

Use this docker image to verify search panic
https://ci.milvus.io:18080/jenkins/blue/organizations/jenkins/build-dev-image/detail/build-dev-image/39/pipeline
harbor.zilliz.cc/milvus-dev/milvus:cydrain-caiyd_20211231_support_coredump_test-308590633-20220127

@yanliang567
Copy link
Contributor

remove urgent label, as it #15133 was fixed in 2.0.1

@yanliang567 yanliang567 removed the priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. label Mar 11, 2022
@wangting0128
Copy link
Contributor Author

verify:benchmark-d4l42

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Issues or changes related a bug test/benchmark benchmark test triage/accepted Indicates an issue or PR is ready to be actively worked on.
Projects
None yet
Development

No branches or pull requests

7 participants