记一次spark中task卡顿引发的血案

记一次spark中task卡顿引发的血案

背景介绍：
由于spark-steaming中其中一个job中某个task卡顿，导致平均30s的平均处理时间的task，整整耗费了10个小时。
问题的排查差不多花费了一周的时间，可以说为解决这个问题，同时掺杂其他工程化的事情，真的一周心情都不好了。
这里特此记录一下吧，给自己做个了断_！嘿嘿~

前言提要：

（1）当前spark采用粗粒度的执行方式，资源申请都是一次性的完成；不存在后期申请不到资源的情况；

（2）数据量很小，每秒100条左右，基本不存在数据倾斜的问题，但是执行的业务流程很复杂；

(3)采用spark on mesos的组粒度模式运行

1.问题描述：

• 2019年12月24日ML处理30个文件时间很异常超过10h；

• xx中部分task处理时间超长，导致整个任务job失败的问题；

1.1 spark ui 卡顿情况

查看spark ui的监控发现，如下图：

图 1 其中的spark中部分task已经卡顿超过10个小时

备注：spark中其中一个task已经卡顿超过10个小时，其他task很快就完成了；

1.2查看服务器日志：

没有发现明显的异常日志，

19/12/27 01:25:45 INFO ContextCleaner: Cleaned RDD 93
19/12/27 01:25:45 INFO BlockManagerInfo: Removed broadcast_49_piece0 on 172.19.32.131:37463 in memory (size: 8.5 KB, free: 3.6 GB)
19/12/27 01:25:45 INFO BlockManagerInfo: Removed broadcast_49_piece0 on 172.19.32.121:46267 in memory (size: 8.5 KB, free: 42.4 GB)
19/12/27 01:25:45 INFO BlockManagerInfo: Removed broadcast_49_piece0 on 172.19.32.68:33141 in memory (size: 8.5 KB, free: 42.3 GB)
19/12/27 01:25:45 INFO BlockManager: Removing RDD 95
19/12/27 01:25:45 INFO ContextCleaner: Cleaned RDD 95
19/12/27 01:25:45 INFO BlockManager: Removing RDD 121
19/12/27 01:25:45 INFO ContextCleaner: Cleaned RDD 121
19/12/27 01:25:45 INFO ContextCleaner: Cleaned shuffle 9
19/12/27 01:26:00 INFO JobScheduler: Added jobs for time 1577409960000 ms
19/12/27 01:27:00 INFO JobScheduler: Added jobs for time 1577410020000 ms
19/12/27 01:28:00 INFO JobScheduler: Added jobs for time 1577410080000 ms
19/12/27 01:29:00 INFO JobScheduler: Added jobs for time 1577410140000 ms
19/12/27 01:30:00 INFO JobScheduler: Added jobs for time 1577410200000 ms
19/12/27 01:31:00 INFO JobScheduler: Added jobs for time 1577410260000 ms
19/12/27 01:32:00 INFO JobScheduler: Added jobs for time 1577410320000 ms
19/12/27 01:33:00 INFO JobScheduler: Added jobs for time 1577410380000 ms
19/12/27 01:34:00 INFO JobScheduler: Added jobs for time 1577410440000 ms
19/12/27 01:35:00 INFO JobScheduler: Added jobs for time 1577410500000 ms
19/12/27 01:36:00 INFO JobScheduler: Added jobs for time 1577410560000 ms
19/12/27 01:37:00 INFO JobScheduler: Added jobs for time 1577410620000 ms
19/12/27 01:38:00 INFO JobScheduler: Added jobs for time 1577410680000 ms
19/12/27 01:39:00 INFO JobScheduler: Added jobs for time 1577410740000 ms

2.问题解决过程

1.怀疑1 ：spark 中由于网络不稳定

错误报异常：spark-submit 超时 Executor heartbeat timed out after 123574 ms
已经排除了内存原因，因为内存很充足；

刚开始认为是网络原因导致一直没有响应，于是增加执行超时时间。

spark-submit 
–conf spark.network.timeout=10000000 \

之后这错误不再报出。

2.怀疑2：某些原因导致task执行太慢

于是采用spark的”推断执行“机制；–不管用

https://blog.csdn.net/baifanwudi/article/details/89377890

https://blog.csdn.net/hanxiaohei99/article/details/91981672

如何开启推测执行
将参数spark.speculation设置为TRUE即可。
spark.speculation=true

相关参数:
spark.speculation.interval 100：检测周期，单位毫秒
spark.speculation.quantile 0.75：完成task的百分比
spark.speculation.multiplier 1.5：时间比例

spark.speculation.interval 参数的意思是设置检测周期，默认100毫秒检测一次是否执行推测执行。
spark.speculation.quantile 参数的意思是同一个stage里面有task完成的百分比，默认为75%。
spark.speculation.multiplier 这个参数是一个时间比例。意思是当task完成了75%的时候，取完成了的task的执行时间的中位数，再乘以这个时间比例，默认为1.5。当未完成的task的执行时间超过了这个乘积值，就开启推测执行。

缺点：推测执行有数据重复的问题，当心！

3.怀疑.查看cpu负载情况----[有效解决问题]

3.1参考到这个：

https://blog.csdn.net/weixin_42340179/article/details/82415085

于是查看cpu

前提是找到对应的executor耗时的task所在的机器

​ 图 2-1 top命令查看进程消耗cpu

​ 图 2-2 top 查看进程中的线程cpu

备注：可以看到进程中的线程cpu之一出现100%的高负载，基本确定是task出现复杂计算（近似死循环）

3.2技术路线：

（1）通过查看CPU参数发现：发现部分task的线程cpu使用100%；可能是复杂的逻辑导致task任务异常超时；（近乎死循环）；
（2）在已经确定cpu高负载的情况下，需要排查业务逻辑部分的个别方法的耗时时间。
决定通过elk来查看各个方法的耗时时间；
（3）根据spark ui，确定了卡顿job的开始时间time和卡顿时刻的机器host名称；最后在elk中添加过滤条件，在结果集中确定最终导致cpu打满的方法method和数据记录名称；
（4）反过来，在去逻辑中测试、修改相应的业务逻辑；

======================================================

最终在elk中定位到该问题。确实是其中的某个方法导致高负载的cpu运算；

hod和数据记录名称；
（4）反过来，在去逻辑中测试、修改相应的业务逻辑；

======================================================

最终在elk中定位到该问题。确实是其中的某个方法导致高负载的cpu运算；