Flink任务 checkPoint失败 问题排查记录

背景

公司有一个实时报表项目，需要使用到flink来进行处理。

处理逻辑大概如下：
需要使用canal监控多张表，然后进行一些复杂计算。

程序设置

flink程序代码里面设置了 checkPoint和自动重启机制

//checkpoint配置
env.enableCheckpointing(300000);
env.getCheckpointConfig().setCheckpointingMode(CheckpointingMode.EXACTLY_ONCE);
env.getCheckpointConfig().setMinPauseBetweenCheckpoints(500);
env.getCheckpointConfig().setCheckpointTimeout(60000);
env.getCheckpointConfig().setMaxConcurrentCheckpoints(1);
env.getCheckpointConfig().setTolerableCheckpointFailureNumber(5);       env.getCheckpointConfig().enableExternalizedCheckpoints(CheckpointConfig.ExternalizedCheckpointCleanup.RETAIN_ON_CANCELLATION);

env.setRestartStrategy(RestartStrategies.failureRateRestart(
                3,
                Time.minutes(5),
                Time.seconds(10)
        ));

但是任务跑一段时间之后，发现任务会一直失败重启。

排查过程

点击任务，进入详情页，查看Exceptions那个模块:

Caused by: org.apache.flink.util.FlinkRuntimeException: Exceeded checkpoint tolerable failure threshold.
    at org.apache.flink.runtime.checkpoint.CheckpointFailureManager.handleCheckpointException(CheckpointFailureManager.java:98)
    at org.apache.flink.runtime.checkpoint.CheckpointFailureManager.handleJobLevelCheckpointException(CheckpointFailureManager.java:67)
    at org.apache.flink.runtime.checkpoint.CheckpointCoordinator.abortPendingCheckpoint(CheckpointCoordinator.java:1915)
    at org.apache.flink.runtime.checkpoint.CheckpointCoordinator.abortPendingCheckpoint(CheckpointCoordinator.java:1888)
    at org.apache.flink.runtime.checkpoint.CheckpointCoordinator.access$600(CheckpointCoordinator.java:94)
    at org.apache.flink.runtime.checkpoint.CheckpointCoordinator$CheckpointCanceller.run(CheckpointCoordinator.java:2029)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

百度了之后解释说：是由于任务的checkpoint重试次数达到了给定的阈值，然后任务失败了。 难道是checkPoint设置有问题？

然后去查看 CheckPoints 这一栏：

点击 History ------》 点击 Refresh

查看任务最近的一次checkPoint情况。

发现任务的checkPoint 失败了5次。 程序里面设置的最多重试5次， 所以任务挂掉了(下面的是正常的checkpoint状态)

点击某一次checkpoint前面的 + 查看每个算子的checkpoint详情(失败的时候，是在某一个算子的地方出现)

可以查看到底是哪个算子在checkpoint的时候出现了问题。

确认问题原因

然后的排查思路就是： 先将任务下线，然后在代码中打印部分日志，修改算子链设置，将每个算子隔离开，并且去掉自动重启任务的配置，仔细查看checkpoint失败的算子的日志

然后将flink 代码修改 设置 禁止自动合并算子

env.disableOperatorChaining();

重新打包上传启动任务。

找到有错的算子这里。 点击它 ，然后进去查看他的日志

可以看到，在任务即将失败重启的时候，出现如下日志：

2021-06-16 15:07:26,168 WARN  org.apache.flink.runtime.taskmanager.Task                    [] - Task 'Interval Join (1/1)#0' did not react to cancelling signal for 30 seconds, but is stuck in method:
 java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:171)
java.net.SocketInputStream.read(SocketInputStream.java:141)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2064)
com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1989)
com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3410)
com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:470)
com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3112)
com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2341)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2736)
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2487)
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
com.report.util.DbUtil.queryKv(DbUtil.java:193)
com.report.function.HuiChatWindowFunction.processElement(HuiChatWindowFunction.java:495)
com.report.function.HuiChatWindowFunction.processElement(HuiChatWindowFunction.java:38)
org.apache.flink.streaming.api.operators.co.IntervalJoinOperator.collect(IntervalJoinOperator.java:274)
org.apache.flink.streaming.api.operators.co.IntervalJoinOperator.processElement(IntervalJoinOperator.java:248)
org.apache.flink.streaming.api.operators.co.IntervalJoinOperator.processElement2(IntervalJoinOperator.java:208)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory.processRecord2(StreamTwoInputProcessorFactory.java:207)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory.lambda$create$1(StreamTwoInputProcessorFactory.java:176)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory$$Lambda$760/267817329.accept(Unknown Source)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory$StreamTaskNetworkOutput.emitRecord(StreamTwoInputProcessorFactory.java:277)
org.apache.flink.streaming.runtime.io.StreamTaskNetworkInput.processElement(StreamTaskNetworkInput.java:204)
org.apache.flink.streaming.runtime.io.StreamTaskNetworkInput.emitNext(StreamTaskNetworkInput.java:174)
org.apache.flink.streaming.runtime.io.StreamOneInputProcessor.processInput(StreamOneInputProcessor.java:65)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessor.processInput(StreamTwoInputProcessor.java:97)
org.apache.flink.streaming.runtime.tasks.StreamTask.processInput(StreamTask.java:396)
org.apache.flink.streaming.runtime.tasks.StreamTask$$Lambda$568/407559166.runDefaultAction(Unknown Source)
org.apache.flink.streaming.runtime.tasks.mailbox.MailboxProcessor.runMailboxLoop(MailboxProcessor.java:191)
org.apache.flink.streaming.runtime.tasks.StreamTask.runMailboxLoop(StreamTask.java:617)
org.apache.flink.streaming.runtime.tasks.StreamTask.invoke(StreamTask.java:581)
org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:755)
org.apache.flink.runtime.taskmanager.Task.run(Task.java:570)
java.lang.Thread.run(Thread.java:748)

2021-06-16 15:07:56,172 WARN  org.apache.flink.runtime.taskmanager.Task                    [] - Task 'Interval Join (1/1)#0' did not react to cancelling signal for 30 seconds, but is stuck in method:
 java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:171)
java.net.SocketInputStream.read(SocketInputStream.java:141)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2064)
com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1989)
com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3410)
com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:470)
com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3112)
com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2341)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2736)
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2487)
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
com.report.util.DbUtil.queryKv(DbUtil.java:193)
com.report.function.HuiChatWindowFunction.processElement(HuiChatWindowFunction.java:495)
com.report.function.HuiChatWindowFunction.processElement(HuiChatWindowFunction.java:38)
org.apache.flink.streaming.api.operators.co.IntervalJoinOperator.collect(IntervalJoinOperator.java:274)
org.apache.flink.streaming.api.operators.co.IntervalJoinOperator.processElement(IntervalJoinOperator.java:248)
org.apache.flink.streaming.api.operators.co.IntervalJoinOperator.processElement2(IntervalJoinOperator.java:208)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory.processRecord2(StreamTwoInputProcessorFactory.java:207)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory.lambda$create$1(StreamTwoInputProcessorFactory.java:176)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory$$Lambda$760/267817329.accept(Unknown Source)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessorFactory$StreamTaskNetworkOutput.emitRecord(StreamTwoInputProcessorFactory.java:277)
org.apache.flink.streaming.runtime.io.StreamTaskNetworkInput.processElement(StreamTaskNetworkInput.java:204)
org.apache.flink.streaming.runtime.io.StreamTaskNetworkInput.emitNext(StreamTaskNetworkInput.java:174)
org.apache.flink.streaming.runtime.io.StreamOneInputProcessor.processInput(StreamOneInputProcessor.java:65)
org.apache.flink.streaming.runtime.io.StreamTwoInputProcessor.processInput(StreamTwoInputProcessor.java:97)
org.apache.flink.streaming.runtime.tasks.StreamTask.processInput(StreamTask.java:396)
org.apache.flink.streaming.runtime.tasks.StreamTask$$Lambda$568/407559166.runDefaultAction(Unknown Source)
org.apache.flink.streaming.runtime.tasks.mailbox.MailboxProcessor.runMailboxLoop(MailboxProcessor.java:191)
org.apache.flink.streaming.runtime.tasks.StreamTask.runMailboxLoop(StreamTask.java:617)
org.apache.flink.streaming.runtime.tasks.StreamTask.invoke(StreamTask.java:581)
org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:755)
org.apache.flink.runtime.taskmanager.Task.run(Task.java:570)
java.lang.Thread.run(Thread.java:748)

大概是这个算子在进行处理的时候，30s没有任何反应，程序卡在了某个方法里面.

可以看到主要的问题在于 代码这一行 (HuiChatWindowFunction.java:495)

Map<String, String> member = DbUtil.queryKv(checkMemberSql, "mysql");

这里是代码里面一个逻辑 需要根据来的数据 去mysql表查询该数据是否满足条件

这个SQL大概是这样的：

select aabm.member_id, acm.contact_account from xxx aabm join xxxx acm where (aabm.member_id = "xxx") or (acm.method_type = 1 and acm.contact_account = "xxxx");

当时写代码时没有考虑到sql的执行效率的问题

这两张表 都比较大，其中一张 几百万的数据，所以如果是join + or的方式进行查询。 速度就会很慢

验证问题原因

从日志里面捞出某一次的查询sql。 去数据库里面进行查询，果然很慢，一直没有返回结果。

所以现在大概确定了，问题确实出在这里。

问题修复

既然 join + or的查询方式 容易长时间没办法返回，从而导致flink任务报错。

那么就把查询逻辑修改一下：

将这个join分开查询，

select * from xxx where member_id = "";
select * from xxx where method_type = 1 and contact_account = "xxxx";

修改之前，我还在数据库里面测试了一下， 基本是秒返回。
就不会出现 stuck的情况了

反思总结

刚开始只根据了 Exceptions里面的日志， 无法确定异常到底出现在哪儿。 误以为是程序checkPoint的设置问题。 一直在对 checkPoint参数进行调整。一开始是加长checkpoint 超时时间， 后面又是增加 checkPoint并行度， 都没有任何效果，浪费了太多时间。

后面慢慢从头到尾梳理之后，从程序里面打印更多的日志到Stdout，然后也实时监控 算子的日志，才算真正找到问题所在。

checkPoint超时失败只是表象，深层次的原因其实是因为任务长时间被阻塞，这才没办法进行checkPoint，所以体现出来的就是 checkpoint超时失败。

当单纯的 Exceptions的日志无法定位问题的时候(或者根据Exceptions里的日志定位到的地方修改之后没有作用)， 需要将程序的日志尽量多的打印出来，在程序失败的时候 准确捞取当时的异常信息， 这样才能准确定位到问题所在