任务变慢
症状:平常执行任务的耗时突然延长 正常5分钟的任务,突然变成了20多分钟,几个大的sql 执行时间是平时的好几倍,而且持续了一周多
结论
阿里云对云机器是有做热迁移导致部分主机的ping 网络是其它主机的延迟几倍,导致了数据网络传输慢
分析过程
- 查看profile有点网络异常但没有在意
- 检查主机间的网络 延迟为毫秒级别、有几台为秒级别没有在意
- 查看服务异常日志没有明显异常
- 下掉几台明显慢的机器,任务恢复(此时还不明原因)
- 上几台新机器的问题出现 此时搞懵了。
- 只能下掉跑起来慢的机器,让任务正常跑,稳住业务,再就进行分析
- SQL语句触发BUG 也解释不通 SQL一直没有变过
- 检查新机器的指令集 无差异
- 检查数据的负载 正常
- 一切看起来都好像是正常的
- 硬着头皮分析源码
- 分析源码得出的结果还是网络问题
- 其中包括调整参数 无效
- 又回到原点 还是怀疑网络问题
- 再次联系运维让所有主机加包互ping 发现大的(秒级别)延迟只锁定在那几台慢机器上,其它正常机器为毫秒级别
- 运维再次联系阿里云才告知做了热迁移,并且给出了时间线
- 与我们的任务异常时间线一核对,正好符合
- 此时基本断定与阿里云有关
查看日志
无明显错误日志(能正常执行完,SQL也没有的错)
详细分析执行计划 抓出异常点
- Last row fetched: 26.6分钟 (1598544688009)
最后一行数据长达26分钟 - KrpcDataStreamSender (dst_id=5) (22.3分钟) 取数分片
主机间的数据交换时过长
正常部分 KrpcDataStreamSender (dst_id=5) (3.0分钟)- InactiveTotalTime: 21.6分钟 网络等待时间
- TotalNetworkSendTime: 21.3分钟
- RowBatchQueuePutWaitTime: 1.9小时 等待入队时间
- EXCHANGE_NODE (id=5) (19.3分钟) 节点交换
- InactiveTotalTime: 19.3分钟
- TotalGetBatchTime: 19.3分钟
- DataWaitTime: 19.3分钟
部分profile
Query Compilation
Metadata of all 3 tables cached: 1毫秒 (1792301)
Analysis finished: 21毫秒 (21566648)
Value transfer graph computed: 21毫秒 (21633422)
Single node plan created: 23毫秒 (23707438)
Runtime filters computed: 23毫秒 (23939894)
Distributed plan created: 24毫秒 (24102220)
Planning finished: 27毫秒 (27576345)
Query Timeline
Query submitted: 0纳秒 (0)
Planning finished: 33毫秒 (33002926)
Submit for admission: 38毫秒 (38003369)
Completed admission: 38毫秒 (38003369)
Ready to start on 19 backends: 40毫秒 (40003547)
All 19 execution backends (57 fragment instances) started: 56毫秒 (56004965)
Last row fetched: 26.6分钟 (1598544688009)
Released admission control resources: 26.6分钟 (1598545688098)
DML data written: 26.6分钟 (1598562689600)
DML Metastore update finished: 26.6分钟 (1598629695523)
Request finished: 26.6分钟 (1598630695611)
Unregister query: 26.6分钟 (1598634695965)
impala后台代码执行时序图(参考)
参考连接
链接: 动态调整Impala日志级别
链接: Impala的信息仓库:解读TQueryExecRequest结构
链接: Impala源码
链接: Krpc 执行缓慢issue
链接: Impala源代码分析(3)-backend查询执行过程
链接: Impala CTAS类操作流程解析
链接: Impala 在网易大数据的优化和实践