[Enhancement]: For a newly created instance on master(v2.6) branch, it takes more than 60 seconds to create a collection

[wangting0128]

Is there an existing issue for this?

• I have searched the existing issues

What would you like to be added?

On the new streamingNode architecture, it takes 60+ seconds to create a collection on a newly deploy instance

as follow:

argo task: bitmap-corn-242gt
test case name: test_bitmap_locust_resource_groups_multi_scalar_streaming_cluster
image: master-20250618-d122e6d1-amd64

server:

NAME                                                              READY   STATUS        RESTARTS        AGE     IP              NODE         NOMINATED NODE   READINESS GATES
bitmap-corn-242gt-9-etcd-0                                        1/1     Running       0               50m     10.104.24.137   4am-node29   <none>           <none>
bitmap-corn-242gt-9-etcd-1                                        1/1     Running       0               50m     10.104.17.235   4am-node23   <none>           <none>
bitmap-corn-242gt-9-etcd-2                                        1/1     Running       0               50m     10.104.33.41    4am-node36   <none>           <none>
bitmap-corn-242gt-9-milvus-datanode-6f96b94887-gwhjw              1/1     Running       2 (50m ago)     50m     10.104.13.99    4am-node16   <none>           <none>
bitmap-corn-242gt-9-milvus-datanode-6f96b94887-n6rzm              1/1     Running       3 (50m ago)     50m     10.104.21.46    4am-node24   <none>           <none>
bitmap-corn-242gt-9-milvus-mixcoord-5886b97965-q4wfh              1/1     Running       3 (50m ago)     50m     10.104.21.45    4am-node24   <none>           <none>
bitmap-corn-242gt-9-milvus-proxy-6f475ccd7-dtr78                  1/1     Running       2 (50m ago)     50m     10.104.14.85    4am-node18   <none>           <none>
bitmap-corn-242gt-9-milvus-querynode-6798c87b8-52n5f              1/1     Running       2 (50m ago)     50m     10.104.14.89    4am-node18   <none>           <none>
bitmap-corn-242gt-9-milvus-querynode-6798c87b8-b4mt6              1/1     Running       2 (50m ago)     50m     10.104.18.101   4am-node25   <none>           <none>
bitmap-corn-242gt-9-milvus-querynode-6798c87b8-fmmdl              1/1     Running       2 (50m ago)     50m     10.104.30.125   4am-node38   <none>           <none>
bitmap-corn-242gt-9-milvus-streamingnode-8486d9b5-nswgk           1/1     Running       3 (50m ago)     50m     10.104.15.246   4am-node20   <none>           <none>
bitmap-corn-242gt-9-milvus-streamingnode-8486d9b5-qr9gm           1/1     Running       3 (50m ago)     50m     10.104.33.22    4am-node36   <none>           <none>
bitmap-corn-242gt-9-milvus-streamingnode-8486d9b5-vt5ww           1/1     Running       2 (50m ago)     50m     10.104.25.213   4am-node30   <none>           <none>
bitmap-corn-242gt-9-minio-0                                       1/1     Running       0               50m     10.104.15.16    4am-node20   <none>           <none>
bitmap-corn-242gt-9-minio-1                                       1/1     Running       0               50m     10.104.17.238   4am-node23   <none>           <none>
bitmap-corn-242gt-9-minio-2                                       1/1     Running       0               50m     10.104.25.218   4am-node30   <none>           <none>
bitmap-corn-242gt-9-minio-3                                       1/1     Running       0               50m     10.104.33.51    4am-node36   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-bookie-0                             1/1     Running       0               50m     10.104.24.142   4am-node29   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-bookie-1                             1/1     Running       0               50m     10.104.15.19    4am-node20   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-bookie-2                             1/1     Running       0               50m     10.104.33.54    4am-node36   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-bookie-init-cfjjz                    0/1     Completed     0               50m     10.104.14.87    4am-node18   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-broker-0                             1/1     Running       0               50m     10.104.14.86    4am-node18   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-broker-1                             1/1     Running       0               50m     10.104.9.43     4am-node14   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-proxy-0                              1/1     Running       0               50m     10.104.30.124   4am-node38   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-proxy-1                              1/1     Running       0               50m     10.104.17.228   4am-node23   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-pulsar-init-qnnbm                    0/1     Completed     0               50m     10.104.30.123   4am-node38   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-recovery-0                           1/1     Running       0               50m     10.104.14.88    4am-node18   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-zookeeper-0                          1/1     Running       0               50m     10.104.15.8     4am-node20   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-zookeeper-1                          1/1     Running       0               50m     10.104.24.141   4am-node29   <none>           <none>
bitmap-corn-242gt-9-pulsarv3-zookeeper-2                          1/1     Running       0               50m     10.104.19.82    4am-node28   <none>           <none>

client log:

[2025-06-18 08:24:23,041 -  INFO - fouram]: [Base] Create collection fouram_SKfYDyuo (base.py:273)
[2025-06-18 08:24:23,041 - DEBUG - fouram]: (api_request)  : [Collection] args: ['fouram_SKfYDyuo', {'auto_id': False, 'description': '', 'fields': [{'name': 'id', 'description': '', 'type': <DataType.INT64: 5>, 'is_primary': True, 'auto_id': False}, {'name': 'float_vector', 'description': '', 'type': <DataType.FLOAT_VECTOR: 101>, 'params': {'dim': 128}}, {'name': 'sparse_float_vector_1', 'description': '', 'type': <DataType.SPARSE_FLOAT_VECTOR: 104>}, {'name': 'int8_1', 'description': '', 'type': <DataType.INT8: 2>}, {'name': 'int16_1', 'description': '', 'type': <DataType.INT16: 3>}, {'name': 'int32_1', 'description': '', 'type': <DataType.INT32: 4>}, {'name': 'int64_1', 'description': '', 'type': <DataType.INT64: 5>}, {'name': 'varchar_1', 'description': '', 'type': <DataType.VARCHAR: 21>, 'params': {'max_length': 256}}, {'name': 'bool_1', 'description': '', 'type': <DataType.BOOL: 1>}, {'name': 'array_int8_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT8: 2>}, {'name': 'array_int16_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT16: 3>}, {'name': 'array_int32_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT32: 4>}, {'name': 'array_int64_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT64: 5>}, {'name': 'array_varchar_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_length': 256, 'max_capacity': 9}, 'element_type': <DataType.VARCHAR: 21>}, {'name': 'array_bool_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.BOOL: 1>}], 'enable_dynamic_field': False}, 'default'], kwargs: {'shards_num': 2, 'client_request_id': '220fa1e5972a42b5ad0f519afa3fa47d'}, [requestId: 220fa1e5972a42b5ad0f519afa3fa47d] (api_request.py:83)
[2025-06-18 08:25:30,191 - DEBUG - fouram]: (api_response) : [Collection] <Collection>:
-------------
<name>: fouram_SKfYDyuo
<description>: 
<schema>: {'auto_id': False, 'description': '', 'fields': [{'name': 'id', 'description': '', 'type': <DataType.INT64: 5>, 'is_primary': True, 'auto_id': False}, {'name': 'float_vector', 'description': '', 'type': <DataType.FLOAT_VECTOR: 101>, 'params': {'dim': 128}}, {'name': 'sparse_float_vector_1', 'description': '', 'type': <DataType.SPARSE_FLOAT_VECTOR: 104>}, {'name': 'int8_1', 'description': '', 'type': <DataType.INT8: 2>}, {'name': 'int16_1', 'description': '', 'type': <DataType.INT16: 3>}, {'name': 'int32_1', 'description': '', 'type': <DataType.INT32: 4>}, {'name': 'int64_1', 'description': '', 'type': <DataType.INT64: 5>}, {'name': 'varchar_1', 'description': '', 'type': <DataType.VARCHAR: 21>, 'params': {'max_length': 256}}, {'name': 'bool_1', 'description': '', 'type': <DataType.BOOL: 1>}, {'name': 'array_int8_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT8: 2>}, {'name': 'array_int16_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT16: 3>}, {'name': 'array_int32_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT32: 4>}, {'name': 'array_int64_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.INT64: 5>}, {'name': 'array_varchar_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_length': 256, 'max_capacity': 9}, 'element_type': <DataType.VARCHAR: 21>}, {'name': 'array_bool_1', 'description': '', 'type': <DataType.ARRAY: 22>, 'params': {'max_capacity': 9}, 'element_type': <DataType.BOOL: 1>}], 'enable_dynamic_field': False}
, [requestId: 220fa1e5972a42b5ad0f519afa3fa47d] (api_request.py:45)
[2025-06-18 08:25:30,192 - DEBUG - fouram]: [Time] Collection run in 67.1502s (api_request.py:52)

Why is this needed?

No response

Anything else?

No response

[xiaofan-luan]

/assign @czs007

[chyezh]

When the cluster startup, streaming node will try to create new topic on pulsar, but the create topic operation with creating producer may be slow.
So the assign channel operation will timeout and perform a backoff, the timeout with backoff will increases the wal unavailable time.
It may be not a critical issue, but just happens when startup of cluster.

[2025/06/18 08:23:58.481 +00:00] [INFO] [adaptor/initializing.go:53] ["start to sync first time tick"] [module=streamingnode] [channel=by-dev-rootcoord-dml_1:rw@4]
[2025/06/18 08:23:58.481 +00:00] [WARN] [adaptor/initializing.go:78] ["send first time tick failed"] [module=streamingnode] [channel=by-dev-rootcoord-dml_1:rw@4] [nextBalanceInterval=14.876346ms] [retryCount=1] [error="allocate timestamp failed: syncTimestamp Failed:context deadline exceeded"]
[2025/06/18 08:25:30.136 +00:00] [INFO] [adaptor/initializing.go:59] ["sync first time tick done"] [module=streamingnode] [channel=by-dev-rootcoord-dml_1:rw@6] [msgID=3/0/0] [timetick=458813637937602369]

[xiaofan-luan]

When the cluster startup, streaming node will try to create new topic on pulsar, but the create topic operation with creating producer may be slow. So the assign channel operation will timeout and perform a backoff, the timeout with backoff will increases the wal unavailable time. It may be not a critical issue, but just happens when startup of cluster.

[2025/06/18 08:23:58.481 +00:00] [INFO] [adaptor/initializing.go:53] ["start to sync first time tick"] [module=streamingnode] [channel=by-dev-rootcoord-dml_1:rw@4]
[2025/06/18 08:23:58.481 +00:00] [WARN] [adaptor/initializing.go:78] ["send first time tick failed"] [module=streamingnode] [channel=by-dev-rootcoord-dml_1:rw@4] [nextBalanceInterval=14.876346ms] [retryCount=1] [error="allocate timestamp failed: syncTimestamp Failed:context deadline exceeded"]
[2025/06/18 08:25:30.136 +00:00] [INFO] [adaptor/initializing.go:59] ["sync first time tick done"] [module=streamingnode] [channel=by-dev-rootcoord-dml_1:rw@6] [msgID=3/0/0] [timetick=458813637937602369]

so we need to create every time at streamNode? can we create it on stream coord?

[chyezh]

I apply smaller backoff configuration in latest master.
/assign @wangting0128
please help to verify it.