插入速度过慢，时间大概需要2分钟左右

Viewed 91
2.1

生成的profile如下：
Summary:
- Profile ID: 88237149325b446a-9dba3df8afbc5fdf
- Task Type: LOAD
- Start Time: 2024-10-29 16:57:42
- End Time: 2024-10-29 16:59:54
- Total: 2m12s
- Task State: OK
- User: root
- Default Db: tmp
- Sql Statement: insert into wudl_doris values (5,1,'广东省','广东省','18575697660')
Execution Summary:
- Parse SQL Time: 0ms
- Nereids Analysis Time: 1ms
- Nereids Rewrite Time: 0ms
- Nereids Optimize Time: 0ms
- Nereids Translate Time: 0ms
- Workload Group:
- Analysis Time: 1ms
- Plan Time: N/A
- JoinReorder Time: N/A
- CreateSingleNode Time: N/A
- QueryDistributed Time: N/A
- Init Scan Node Time: N/A
- Finalize Scan Node Time: N/A
- Get Splits Time: N/A
- Get Partitions Time: N/A
- Get Partition Files Time: N/A
- Create Scan Range Time: N/A
- Schedule Time: N/A
- Fragment Assign Time: N/A
- Fragment Serialize Time: 0ms
- Fragment RPC Phase1 Time: 2ms
- Fragment RPC Phase2 Time: N/A
- Fragment Compressed Size: 1.98 KB
- Fragment RPC Count: 1
- Wait and Fetch Result Time: N/A
- Fetch Result Time: 0ms
- Write Result Time: 0ms
- Doris Version: doris-2.1.5-rc02-d5a02e095d
- Is Nereids: Yes
- Is Pipeline: Yes
- Is Cached: No
- Total Instances Num: 1
- Instances Num Per BE: 11.6.2.53:6060:1
- Parallel Fragment Exec Instance Num: 13
- Trace ID:
- Transaction Commit Time: N/A

MergedProfile
Fragments:
Fragment 0:
Pipeline : 0(instance_num=1):
OLAP_TABLE_SINK_OPERATOR (id=0):
- CloseTime: avg 4.682us, max 4.682us, min 4.682us
- ExecTime: avg 8.974us, max 8.974us, min 8.974us
- InitTime: avg 0ns, max 0ns, min 0ns
- InputRows: sum 1, avg 1, max 1, min 1
- MemoryUsage: sum , avg , max , min
- PeakMemoryUsage: sum 0.00 , avg 0.00 , max 0.00 , min 0.00
- OpenTime: avg 650.76us, max 650.76us, min 650.76us
- WaitForDependency[AsyncWriterDependency]Time: avg 0ns, max 0ns, min 0ns
UNION_OPERATOR (id=0):
- PlanInfo
- constant exprs:
- 5 | 1 | CAST('广东省' AS TEXT) | '广东省' | '18575697660'
- BlocksProduced: sum 1, avg 1, max 1, min 1
- CloseTime: avg 0ns, max 0ns, min 0ns
- ExecTime: avg 55.378us, max 55.378us, min 55.378us
- InitTime: avg 3.221us, max 3.221us, min 3.221us
- MemoryUsage: sum , avg , max , min
- PeakMemoryUsage: sum 0.00 , avg 0.00 , max 0.00 , min 0.00
- OpenTime: avg 4.250us, max 4.250us, min 4.250us
- ProjectionTime: avg 0ns, max 0ns, min 0ns
- RowsProduced: sum 1, avg 1, max 1, min 1
- WaitForDependency[UNION_OPERATOR_DEPENDENCY]Time: avg 0ns, max 0ns, min 0ns

Execution Profile 88237149325b446a-9dba3df8afbc5fdf:(Active: 2m12s, % non-child: 0.00%)
Fragments:
Fragment 0:
Pipeline :0 (host=TNetworkAddress(hostname:11.6.2.53, port:7050)):
PipelineXTask (index=0):(Active: 216.655us, % non-child: 0.00%)
- CoreChangeTimes: 0
- ExecuteTime: 91.616us
- CloseTime: 8.820us
- GetBlockTime: 48.656us
- OpenTime: 23.464us
- PrepareTime: 83.124us
- SinkTime: 4.980us
- GetBlockCounter: 1
- NumBlockedBySinkTimes: 0
- NumBlockedBySrcTimes: 0
- NumBlockedTimes: 1
- NumScheduleTimes: 2
- NumYieldTimes: 0
- PendingFinishTimes: 1
- TaskCpuTime: 199.48us
- WaitBfTime: 0ns
- WaitBfTimes: 0
- WaitDenpendencyTimes: 0
- WaitWorkerTime: 159.894us
OLAP_TABLE_SINK_OPERATOR (id=0):(Active: 2m12s, % non-child: 0.00%)
- CloseTime: 4.682us
- CloseWaitTime: 2m12s
- ExecTime: 8.974us
- InitTime: 0ns
- InputRows: 1
- MaxAddBatchExecTime: 28.608ms
- MaxWaitExecTime: 19.0us
- MemoryUsage:
- PeakMemoryUsage: 0.00
- NonBlockingSendTime: 2.856ms
- NonBlockingSendWorkTime: 117.653us
- SerializeBatchTime: 16.823us
- NumberBatchAdded: 3
- NumberNodeChannels: 3
- OpenTime: 650.76us
- PendingFinishDependency: 2m12s
- RowsFiltered: 0
- RowsProduced: 0
- RowsRead: 1
- SendDataTime: 108.855us
- AddPartitionRequestTime: 0ns
- AppendNodeChannelTime: 30.847us
- FilterTime: 0ns
- RowDistributionTime: 52.792us
- WaitMemLimitTime: 0ns
- WhereClauseTime: 0ns
- TotalAddBatchExecTime: 2m14s
- TotalWaitExecTime: 142.0us
- ValidateDataTime: 11.344us
- WaitForDependency[AsyncWriterDependency]Time: 0ns
UNION_OPERATOR (id=0):
- BlocksProduced: 1
- CloseTime: 0ns
- ExecTime: 55.378us
- InitTime: 3.221us
- MemoryUsage:
- PeakMemoryUsage: 0.00
- OpenTime: 4.250us
- ProjectionTime: 0ns
- RowsProduced: 1
- WaitForDependency[UNION_OPERATOR_DEPENDENCY]Time: 0ns
LoadChannels:

wangcool13
2 Answers

从这两个点看看的：
1、写入慢时，cpu/mem/io是否使用率过高导致集群负载了
2、wudl_doris表在写入时，是否有其它schema change的操作

张彬华7323

大神，昨天又复现一次，情况如下，请帮忙分析一下，多谢多谢。其中出现本情况时，wudl_doris表在写入时，没有其它schema change的操作。

1 profile-2024-10-30 14:29:19

Summary:
- Profile ID: 6bbf264a53bf4da7-838c39206c710b1e
- Task Type: LOAD
- Start Time: 2024-10-30 14:29:19
- End Time: 2024-10-30 14:32:02
- Total: 2m42s
- Task State: OK
- User: root
- Default Db: tmp
- Sql Statement: insert into wudl_doris values (6,1,'广东省','广东省','18575697660')
Execution Summary:
- Parse SQL Time: N/A
- Nereids Analysis Time: 1ms
- Nereids Rewrite Time: 0ms
- Nereids Optimize Time: 0ms
- Nereids Translate Time: 0ms
- Workload Group:
- Analysis Time: 1ms
- Plan Time: N/A
- JoinReorder Time: N/A
- CreateSingleNode Time: N/A
- QueryDistributed Time: N/A
- Init Scan Node Time: N/A
- Finalize Scan Node Time: N/A
- Get Splits Time: N/A
- Get Partitions Time: N/A
- Get Partition Files Time: N/A
- Create Scan Range Time: N/A
- Schedule Time: N/A
- Fragment Assign Time: N/A
- Fragment Serialize Time: 0ms
- Fragment RPC Phase1 Time: 2ms
- Fragment RPC Phase2 Time: N/A
- Fragment Compressed Size: 1.98 KB
- Fragment RPC Count: 1
- Wait and Fetch Result Time: N/A
- Fetch Result Time: 0ms
- Write Result Time: 0ms
- Doris Version: doris-2.1.5-rc02-d5a02e095d
- Is Nereids: Yes
- Is Pipeline: Yes
- Is Cached: No
- Total Instances Num: 1
- Instances Num Per BE: 11.6.2.54:6060:1
- Parallel Fragment Exec Instance Num: 13
- Trace ID:
- Transaction Commit Time: N/A

MergedProfile
Fragments:
Fragment 0:
Pipeline : 0(instance_num=1):
OLAP_TABLE_SINK_OPERATOR (id=0):
- CloseTime: avg 4.262us, max 4.262us, min 4.262us
- ExecTime: avg 7.664us, max 7.664us, min 7.664us
- InitTime: avg 0ns, max 0ns, min 0ns
- InputRows: sum 1, avg 1, max 1, min 1
- MemoryUsage: sum , avg , max , min
- PeakMemoryUsage: sum 0.00 , avg 0.00 , max 0.00 , min 0.00
- OpenTime: avg 871.548us, max 871.548us, min 871.548us
- WaitForDependency[AsyncWriterDependency]Time: avg 0ns, max 0ns, min 0ns
UNION_OPERATOR (id=0):
- PlanInfo
- constant exprs:
- 6 | 1 | CAST('广东省' AS TEXT) | '广东省' | '18575697660'
- BlocksProduced: sum 1, avg 1, max 1, min 1
- CloseTime: avg 0ns, max 0ns, min 0ns
- ExecTime: avg 43.99us, max 43.99us, min 43.99us
- InitTime: avg 2.589us, max 2.589us, min 2.589us
- MemoryUsage: sum , avg , max , min
- PeakMemoryUsage: sum 0.00 , avg 0.00 , max 0.00 , min 0.00
- OpenTime: avg 6.527us, max 6.527us, min 6.527us
- ProjectionTime: avg 0ns, max 0ns, min 0ns
- RowsProduced: sum 1, avg 1, max 1, min 1
- WaitForDependency[UNION_OPERATOR_DEPENDENCY]Time: avg 0ns, max 0ns, min 0ns

Execution Profile 6bbf264a53bf4da7-838c39206c710b1e:(Active: 2m42s, % non-child: 0.00%)
Fragments:
Fragment 0:
Pipeline :0 (host=TNetworkAddress(hostname:11.6.2.54, port:7050)):
PipelineXTask (index=0):(Active: 187.16us, % non-child: 0.00%)
- CoreChangeTimes: 0
- ExecuteTime: 70.774us
- CloseTime: 7.988us
- GetBlockTime: 34.917us
- OpenTime: 17.956us
- PrepareTime: 85.939us
- SinkTime: 3.927us
- GetBlockCounter: 1
- NumBlockedBySinkTimes: 0
- NumBlockedBySrcTimes: 0
- NumBlockedTimes: 1
- NumScheduleTimes: 2
- NumYieldTimes: 0
- PendingFinishTimes: 1
- TaskCpuTime: 168.453us
- WaitBfTime: 0ns
- WaitBfTimes: 0
- WaitDenpendencyTimes: 0
- WaitWorkerTime: 16.993us
OLAP_TABLE_SINK_OPERATOR (id=0):(Active: 2m42s, % non-child: 0.00%)
- CloseTime: 4.262us
- CloseWaitTime: 2m42s
- ExecTime: 7.664us
- InitTime: 0ns
- InputRows: 1
- MaxAddBatchExecTime: 30.319ms
- MaxWaitExecTime: 19.0us
- MemoryUsage:
- PeakMemoryUsage: 0.00
- NonBlockingSendTime: 2.193ms
- NonBlockingSendWorkTime: 169.760us
- SerializeBatchTime: 31.691us
- NumberBatchAdded: 3
- NumberNodeChannels: 3
- OpenTime: 871.548us
- PendingFinishDependency: 2m42s
- RowsFiltered: 0
- RowsProduced: 0
- RowsRead: 1
- SendDataTime: 85.499us
- AddPartitionRequestTime: 0ns
- AppendNodeChannelTime: 10.681us
- FilterTime: 0ns
- RowDistributionTime: 51.606us
- WaitMemLimitTime: 0ns
- WhereClauseTime: 0ns
- TotalAddBatchExecTime: 2m43s
- TotalWaitExecTime: 71.0us
- ValidateDataTime: 14.513us
- WaitForDependency[AsyncWriterDependency]Time: 0ns
UNION_OPERATOR (id=0):
- BlocksProduced: 1
- CloseTime: 0ns
- ExecTime: 43.99us
- InitTime: 2.589us
- MemoryUsage:
- PeakMemoryUsage: 0.00
- OpenTime: 6.527us
- ProjectionTime: 0ns
- RowsProduced: 1
- WaitForDependency[UNION_OPERATOR_DEPENDENCY]Time: 0ns
LoadChannels:

2 服务器负载信息

2.1 CPU average load

image.png

2.2 IO利用率

image.png

2.3 可用内存

image.png

2.4 网络-万兆网卡

image.png
image.png

2.5 iostat -dxk 1（2台IO比较高的服务器，看的时候sql已经执行完毕）

image.png
image.png

2.6 iotop（2台IO比较高的服务器，看的时候sql已经执行完毕）

image.png
image.png

wangcool13