为了更快的定位您的问题,请提供以下信息,谢谢
【详述】问题详细描述
stream load 导入耗时十几秒,甚至达到三十几秒,最终成功,写入诊断分析中显示 OpenTime 耗时很久。
【背景】做过哪些操作?
重启 fe 和 cn 服务之后,出现了这个问题。
【业务影响】
stream load 写入巨慢,写入客户端出现数据堆积。
【是否存算分离】
是
【StarRocks版本】
3.2.6
【集群规模】
k8s 部署,3fe+6cn
【机器信息】CPU虚拟核/内存/网卡
fe: 4C/16G/万兆
fe: 8C/32G/万兆
【表模型】
明细表
【导入或者导出方式】
go-client stream load 普通
【联系方式】为了在解决问题过程中能及时联系到您获取一些日志信息,请补充下您的联系方式
StarRocks 3.0-存算分离用户群-Seema
【附件】
- cn.INFO 一次导入日志
I0731 10:56:15.010823 621 stream_load.cpp:240] new income streaming load request.id=664e99760e714fb7-94ff8303d885b39d, job_id=-1, txn_id: -1, label=6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, db=db_2000003485, db=db_2000003485, tbl=tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS
I0731 10:56:15.010841 621 stream_load.cpp:245] streaming load request: HttpRequest:
method:1
uri:/api/db_2000003485/tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS/_stream_load
raw_path:/api/db_2000003485/tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS/_stream_load
headers:
key=Accept-Encoding, value=gzip
key=Referer, value=http://xxx:8030/api/db_2000003485/tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS/_stream_load
key=Read_json_by_line, value=true
key=Label, value=6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8
key=Ignore_json_size, value=true
key=Format, value=json
key=Expect, value=100-continue
key=Authorization, value=Basic YWRtaW46MTIzNDU2
key=Content-Length, value=12304
key=User-Agent, value=Go-http-client/1.1
key=Connection, value=close
key=Host, value=xxx:8040
params:
key=db, value=db_2000003485
key=table, value=tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS
I0731 10:56:15.032269 621 stream_load_executor.cpp:76] begin to execute job. label=6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, txn_id: 1985987, query_id=664e9976-0e71-4fb7-94ff-8303d885b39d
I0731 10:56:42.374020 3819 heartbeat_server.cpp:94] Updating master info: TMasterInfo(network_address=TNetworkAddress(hostname=starrocks-fe-2.starrocks-fe-search.starrocks-95a6216e-289d.svc.cluster.local, port=9020), cluster_id=12345, epoch=5, token=8091cced-f35c-4551-ac7d-abc878550185, backend_ip=starrocks-cn-5.starrocks-cn-search.starrocks-95a6216e-289d.svc.cluster.local, http_port=8030, heartbeat_flags=0, backend_id=147379, min_active_txn_id=1985987, run_mode=SHARED_DATA)
I0731 10:56:52.516494 367 tablet_sink_index_channel.cpp:757] OlapTableSink txn_id: 1985987 load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d commit 1 tablets: 145075
I0731 10:56:52.516512 367 tablet_sink_index_channel.cpp:757] OlapTableSink txn_id: 1985987 load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d commit 1 tablets: 145076
I0731 10:56:52.516516 367 tablet_sink_index_channel.cpp:757] OlapTableSink txn_id: 1985987 load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d commit 1 tablets: 145074
I0731 10:56:52.516520 367 tablet_sink_index_channel.cpp:757] OlapTableSink txn_id: 1985987 load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d commit 1 tablets: 145072
I0731 10:56:52.516525 367 tablet_sink_index_channel.cpp:757] OlapTableSink txn_id: 1985987 load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d commit 1 tablets: 145073
I0731 10:56:52.516530 367 tablet_sink_index_channel.cpp:757] OlapTableSink txn_id: 1985987 load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d commit 1 tablets: 145071
I0731 10:56:52.516537 367 tablet_sink_sender.cpp:332] Olap table sink statistics. load_id: 664e9976-0e71-4fb7-94ff-8303d885b39d, txn_id: 1985987, add chunk time(ms)/wait lock time(ms)/num: {10108:(45)(0)(1)} {147379:(41)(0)(1)} {10111:(107)(0)(1)} {10044:(81)(0)(1)} {10109:(49)(0)(1)} {10110:(43)(0)(1)}
I0731 10:56:52.517351 367 plan_fragment_executor.cpp:493] Fragment 664e9976-0e71-4fb7-94ff-8303d885b39e:(Active: 112.576ms, non-child: 0.00%)
- InstanceAllocatedMemoryUsage: 439.93 KB
- InstanceDeallocatedMemoryUsage: 80.73 KB
- InstancePeakMemoryUsage: 359.20 KB
- MemoryLimit: -1.00 B
- RowsProduced: 16
OlapTableSink:(Active: 37s479ms, non-child: 100.00%)- TxnID: 1985987
- IndexNum: 1
- ReplicatedStorage: true
- AutomaticPartition: false
- AutomaticBucketSize: 4294967296
- AllocAutoIncrementTime: 520.000ns
- CloseWaitTime: 111.706ms
- OpenTime: 37s366ms
- PrepareDataTime: 20.458us
- ConvertChunkTime: 3.930us
- ValidateDataTime: 5.331us
- RowsFiltered: 0
- RowsRead: 16
- RowsReturned: 16
- RpcClientSideTime: 372.303ms
- RpcServerSideTime: 368.962ms
- RpcServerWaitFlushTime: 0.000ns
- SendDataTime: 278.584us
- PackChunkTime: 55.956us
- SendRpcTime: 140.185us
- CompressTime: 0.000ns
- SerializeChunkTime: 38.859us
- WaitResponseTime: 0.000ns
FILE_SCAN_NODE (id=0):(Active: 538.301us, non-child: 0.48%)
- BytesRead: 0
- IOTaskExecTime: 0.000ns
- IOTaskWaitTime: 0.000ns
- NumDiskAccess: 0
- PeakMemoryUsage: 0
- RowsRead: 0
- RowsReturned: 16
- RowsReturnedRate: 29.72 K/sec
- ScanTime: 333.546us
- ScannerQueueCounter: 1
- ScannerQueueTime: 3.541us
- ScannerThreadsInvoluntaryContextSwitches: 0
- ScannerThreadsTotalWallClockTime: 0.000ns
- MaterializeTupleTime(*): 0.000ns
- ScannerThreadsSysTime: 0.000ns
- ScannerThreadsUserTime: 0.000ns
- ScannerThreadsVoluntaryContextSwitches: 0
- TotalRawReadTime(*): 0.000ns
- TotalReadThroughput: 0.00 /sec
DataSource:- DataSourceType: FileDataSource
- FileScanner: 0
- CastChunkTime: 25.269us
- CreateChunkTime: 39.801us
- FileReadCount: 2
- FileReadTime: 2.335us
- FillTime: 0.000ns
- MaterializeTime: 9.722us
- ReadTime: 0.000ns
- ScannerTotalTime: 200.231us
I0731 10:56:52.600584 621 stream_load.cpp:141] streaming load response: {
“TxnId”: 1985987,
“Label”: “6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8”,
“Status”: “Success”,
“Message”: “OK”,
“NumberTotalRows”: 16,
“NumberLoadedRows”: 16,
“NumberFilteredRows”: 0,
“NumberUnselectedRows”: 0,
“LoadBytes”: 12304,
“LoadTimeMs”: 37589,
“BeginTxnTimeMs”: 0,
“StreamLoadPlanTimeMs”: 21,
“ReadDataTimeMs”: 0,
“WriteDataTimeMs”: 37485,
“CommitAndPublishTimeMs”: 83
}
fe.log 日志:
2024-07-31 10:56:15.007+08:00 INFO (nioEventLoopGroup-6-1|132) [LoadAction.executeWithoutPasswordInternal():139] redirect load action to destination=TNetworkAddress(hostname:xxx.140, port:8040), db: db_2000003485, tbl: tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS, label: 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8
2024-07-31 10:56:15.011+08:00 INFO (thrift-server-pool-12|155) [FrontendServiceImpl.loadTxnBegin():1303] receive txn begin request, db: db_2000003485, tbl: tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS, label: 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, backend: xxx.140
2024-07-31 10:56:15.011+08:00 INFO (thrift-server-pool-12|155) [DatabaseTransactionMgr.beginTransaction():319] begin transaction: txn_id: 1985987 with label 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8 from coordinator BE: xxx, listner id: -1
2024-07-31 10:56:15.011+08:00 INFO (thrift-server-pool-13|156) [FrontendServiceImpl.streamLoadPut():1730] receive stream load put request. db:db_2000003485, tbl: tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS, txn_id: 1985987, load id: 664e9976-0e71-4fb7-94ff-8303d885b39d, backend: xxx.140
2024-07-31 10:56:15.028+08:00 INFO (thrift-server-pool-13|156) [StreamLoadPlanner.plan():293] load job id: 664e9976-0e71-4fb7-94ff-8303d885b39d, txn id: 1985987, parallel: 0, compress: NO_COMPRESSION, replicated: true, quorum: MAJORITY
2024-07-31 10:56:41.537+08:00 INFO (autovacuum-pool1-t1|202) [AutovacuumDaemon.vacuumPartitionImpl():201] Vacuumed db_2000003485.tb_2000003485__starrocks__copied_online_klog_services__4273a6a3__VSKMug.144700 hasError=false vacuumedFiles=42 vacuumedFileSize=0 visibleVersion=31 minRetainVersion=31 minActiveTxnId=1985987 cost=203ms
2024-07-31 10:56:45.569+08:00 INFO (autovacuum-pool1-t7|208) [AutovacuumDaemon.vacuumPartitionImpl():201] Vacuumed db_2000003485.tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS.145070 hasError=false vacuumedFiles=114 vacuumedFileSize=992219 visibleVersion=269 minRetainVersion=269 minActiveTxnId=1985987 cost=234ms
2024-07-31 10:56:49.419+08:00 INFO (autovacuum-pool1-t8|209) [AutovacuumDaemon.vacuumPartitionImpl():201] Vacuumed db_2000003485.tb_2000003485__starrocks__copied_sync_monitor__01eca44e__76Pt3M.148136 hasError=false vacuumedFiles=24 vacuumedFileSize=0 visibleVersion=361 minRetainVersion=361 minActiveTxnId=1985987 cost=82ms
2024-07-31 10:56:52.517+08:00 INFO (thrift-server-pool-12|155) [FrontendServiceImpl.loadTxnCommit():1401] receive txn commit request. db: db_2000003485, tbl: tb_2000003485__starrocks__copied_ks3_project_2000159590__1569e819__h4YboS, txn_id: 1985987, backend: xxx.140
2024-07-31 10:56:52.519+08:00 INFO (thrift-server-pool-12|155) [DatabaseTransactionMgr.commitTransaction():468] transaction:[TransactionState. txn_id: 1985987, label: 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, db id: 10113, table id list: 79362, callback id: -1, coordinator: BE: xxx.140, transaction status: COMMITTED, error replicas num: 0, replica ids: , prepare time: 1722394575011, write end time: 1722394612517, allow commit time: -1, commit time: 1722394612517, finish time: -1, write cost: 37506ms, reason: attachment: com.starrocks.load.loadv2.ManualLoadTxnCommitAttachment@29ad56a5 tabletCommitInfos size: 6] successfully committed
2024-07-31 10:56:52.600+08:00 INFO (lake-publish-task-27448|30110) [DatabaseTransactionMgr.finishTransaction():1099] finish transaction TransactionState. txn_id: 1985987, label: 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, db id: 10113, table id list: 79362, callback id: -1, coordinator: BE: xxx.140, transaction status: VISIBLE, error replicas num: 0, replica ids: , prepare time: 1722394575011, write end time: 1722394612517, allow commit time: -1, commit time: 1722394612517, finish time: 1722394612598, write cost: 37506ms, publish total cost: 81ms, total cost: 37587ms, reason: attachment: com.starrocks.load.loadv2.ManualLoadTxnCommitAttachment@29ad56a5 tabletCommitInfos size: 6 successfully
2024-07-31 11:10:29.284+08:00 INFO (leaderCheckpointer|189) [DatabaseTransactionMgr.replayUpsertTransactionState():1694] replay a committed transaction TransactionState. txn_id: 1985987, label: 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, db id: 10113, table id list: 79362, callback id: -1, coordinator: BE: xxx.1400, transaction status: COMMITTED, error replicas num: 0, replica ids: , prepare time: 1722394575011, write end time: -1, allow commit time: -1, commit time: 1722394612517, finish time: -1, write cost: 37506ms, reason: attachment: com.starrocks.load.loadv2.ManualLoadTxnCommitAttachment@2caf0f96
2024-07-31 11:10:29.284+08:00 INFO (leaderCheckpointer|189) [DatabaseTransactionMgr.replayUpsertTransactionState():1697] replay a visible transaction TransactionState. txn_id: 1985987, label: 6e3af0e3-d7b8-418c-adb3-b3b6d41d31d8, db id: 10113, table id list: 79362, callback id: -1, coordinator: BE: xxx.140, transaction status: VISIBLE, error replicas num: 0, replica ids: , prepare time: 1722394575011, write end time: -1, allow commit time: -1, commit time: 1722394612517, finish time: 1722394612598, write cost: 37506ms, publish total cost: 81ms, total cost: 37587ms, reason: attachment: com.starrocks.load.loadv2.ManualLoadTxnCommitAttachment@2b89dbca