flink启动job随机卡住故障排查

故障表现

在启动 job 时随机出现 checkpoint 无法完成的情况

但只要 job 能够正常跑起来就一直都没有问题

没有任何的错误日志

背景环境

在腾讯云的 k8s 上搭建的 flink standalone in k8s 模式, 版本是 flink:1.11.3

Flink 的 CheckPoint 存储用的是腾讯云的 NFS

排查思路

猜测: 怀疑是 NFS 的问题

直接去掉 NFS 挂载, 使用本地文件存储 checkpoint, 问题表现依旧

故障和 nfs 存储无关

猜测: 怀疑是部署环境导致的

因为我们使用的是 helm 包安装的, 并且 k8s 里面有其他服务

直接重新购买了一套独立 k8s 集群, 通过官方的 yaml 部署, 问题表现依旧

故障和配置环境无关

目前看来故障和配置, 环境, 存储无关

猜测: job 代码的问题

从 flink 官方上下载了 Example, 跑了十几次都没有问题

基本确定是 job 代码的问题

告警日志的线索

仔细查看下 taskamanger 的日志, 发现了个重要的线索

2021-03-02 15:49:59,091 WARN  org.apache.flink.runtime.taskmanager.Task                    [] - Task 'Source: 配置广播流,GameId=17 (1/1)' did not react to cancelling signal for 30 seconds, but is stuck in method:
 sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
java.lang.Class.newInstance(Class.java:442)
java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
java.util.ServiceLoader$1.next(ServiceLoader.java:480)
java.sql.DriverManager$2.run(DriverManager.java:603)
java.sql.DriverManager$2.run(DriverManager.java:583)
java.security.AccessController.doPrivileged(Native Method)
java.sql.DriverManager.loadInitialDrivers(DriverManager.java:583)
java.sql.DriverManager.<clinit>(DriverManager.java:101)
org.mariadb.jdbc.Driver.<clinit>(Driver.java:70)
java.lang.Class.forName0(Native Method)
java.lang.Class.forName(Class.java:264)
org.apache.flink.connector.jdbc.internal.connection.SimpleJdbcConnectionProvider.getConnection(SimpleJdbcConnectionProvider.java:52)
com.funjoy.flink.ConfigSourceFunction.open(ConfigSourceFunction.java:52)
org.apache.flink.api.common.functions.util.FunctionUtils.openFunction(FunctionUtils.java:36)
org.apache.flink.streaming.api.operators.AbstractUdfStreamOperator.open(AbstractUdfStreamOperator.java:102)
org.apache.flink.streaming.runtime.tasks.OperatorChain.initializeStateAndOpenOperators(OperatorChain.java:291)
org.apache.flink.streaming.runtime.tasks.StreamTask.lambda$beforeInvoke$1(StreamTask.java:506)
org.apache.flink.streaming.runtime.tasks.StreamTask$$Lambda$621/13894355.run(Unknown Source)
org.apache.flink.streaming.runtime.tasks.StreamTaskActionExecutor$SynchronizedStreamTaskActionExecutor.runThrowing(StreamTaskActionExecutor.java:92)
org.apache.flink.streaming.runtime.tasks.StreamTask.beforeInvoke(StreamTask.java:475)
org.apache.flink.streaming.runtime.tasks.StreamTask.invoke(StreamTask.java:526)
org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:721)
org.apache.flink.runtime.taskmanager.Task.run(Task.java:546)
java.lang.Thread.run(Thread.java:748)

2021-03-02 15:50:29,065 WARN  org.apache.flink.runtime.taskmanager.Task                    [] - Task 'Source: 日数据流,GameId=17 (1/1)' did not react to cancelling signal for 30 seconds, but is stuck in method:
 ru.yandex.clickhouse.ClickHouseDriver.<clinit>(ClickHouseDriver.java:38)
java.lang.Class.forName0(Native Method)
java.lang.Class.forName(Class.java:264)
org.apache.flink.connector.jdbc.internal.connection.SimpleJdbcConnectionProvider.getConnection(SimpleJdbcConnectionProvider.java:52)
com.funjoy.flink.DailySourceFunction.open(DailySourceFunction.java:69)
org.apache.flink.api.common.functions.util.FunctionUtils.openFunction(FunctionUtils.java:36)
org.apache.flink.streaming.api.operators.AbstractUdfStreamOperator.open(AbstractUdfStreamOperator.java:102)
org.apache.flink.streaming.runtime.tasks.OperatorChain.initializeStateAndOpenOperators(OperatorChain.java:291)
org.apache.flink.streaming.runtime.tasks.StreamTask.lambda$beforeInvoke$1(StreamTask.java:506)
org.apache.flink.streaming.runtime.tasks.StreamTask$$Lambda$621/13894355.run(Unknown Source)
org.apache.flink.streaming.runtime.tasks.StreamTaskActionExecutor$SynchronizedStreamTaskActionExecutor.runThrowing(StreamTaskActionExecutor.java:92)
org.apache.flink.streaming.runtime.tasks.StreamTask.beforeInvoke(StreamTask.java:475)
org.apache.flink.streaming.runtime.tasks.StreamTask.invoke(StreamTask.java:526)
org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:721)
org.apache.flink.runtime.taskmanager.Task.run(Task.java:546)
java.lang.Thread.run(Thread.java:748)

这么两个 waring, 基本上符合我们的故障现象,

怀疑是因为建立 clickhouse 连接时卡住了

因为 job 一直卡住了, 所以在执行 cancel 时无法处理, 超过 30 秒后直接出现 waring

通过上面的堆栈, 发现是获取 clickhouse 和 mariadb 连接时出现的问题

将连接 clickhouse 相关的代码注释后就正常了
所以基本上确定故障表现和连接 clickhouse 有一定关系.

在卡住的时候我们通过其他客户端连接 clickhouse 正常, 所以故障和 clickhouse 服务无关

我们找了阿里云的专家帮忙, 查看了 taskmanager 和 jobmanager 的日志后
建议我们在 checkpoint 卡住的时候用jstack查看下线程在做什么

Source: 日数据流,GameId=17 (1/1)" #62 prio=5 os_prio=0 tid=0x00007f3da008d000 nid=0x156 in Object.wait() [0x00007f3e48fcb000]
   java.lang.Thread.State: RUNNABLE
    at ru.yandex.clickhouse.ClickHouseDriver.<clinit>(ClickHouseDriver.java:38)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:264)
    at org.apache.flink.connector.jdbc.internal.connection.SimpleJdbcConnectionProvider.getConnection(SimpleJdbcConnectionProvider.java:52)
    - locked <0x00000007db8a3bf8> (a org.apache.flink.connector.jdbc.internal.connection.SimpleJdbcConnectionProvider)
    at com.funjoy.flink.DailySourceFunction.open(DailySourceFunction.java:69)
    at org.apache.flink.api.common.functions.util.FunctionUtils.openFunction(FunctionUtils.java:36)
    at org.apache.flink.streaming.api.operators.AbstractUdfStreamOperator.open(AbstractUdfStreamOperator.java:102)
    at org.apache.flink.streaming.runtime.tasks.OperatorChain.initializeStateAndOpenOperators(OperatorChain.java:291)
    at org.apache.flink.streaming.runtime.tasks.StreamTask.lambda$beforeInvoke$1(StreamTask.java:506)
    at org.apache.flink.streaming.runtime.tasks.StreamTask$$Lambda$617/1628357580.run(Unknown Source)
    at org.apache.flink.streaming.runtime.tasks.StreamTaskActionExecutor$SynchronizedStreamTaskActionExecutor.runThrowing(StreamTaskActionExecutor.java:92)
    - locked <0x00000007db8a3e00> (a java.lang.Object)
    at org.apache.flink.streaming.runtime.tasks.StreamTask.beforeInvoke(StreamTask.java:475)
    at org.apache.flink.streaming.runtime.tasks.StreamTask.invoke(StreamTask.java:526)
    at org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:721)
    at org.apache.flink.runtime.taskmanager.Task.run(Task.java:546)
    at java.lang.Thread.run(Thread.java:748)

Source: 配置广播流,GameId=17 (1/1)" #63 prio=5 os_prio=0 tid=0x00007f3da008f000 nid=0x157 in Object.wait() [0x00007f3e48ec8000]
   java.lang.Thread.State: RUNNABLE
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at java.lang.Class.newInstance(Class.java:442)
    at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
    at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
    at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
    at java.sql.DriverManager$2.run(DriverManager.java:603)
    at java.sql.DriverManager$2.run(DriverManager.java:583)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.sql.DriverManager.loadInitialDrivers(DriverManager.java:583)
    at java.sql.DriverManager.<clinit>(DriverManager.java:101)
    at org.mariadb.jdbc.Driver.<clinit>(Driver.java:70)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:264)
    at org.apache.flink.connector.jdbc.internal.connection.SimpleJdbcConnectionProvider.getConnection(SimpleJdbcConnectionProvider.java:52)
    - locked <0x00000007db8a35c0> (a org.apache.flink.connector.jdbc.internal.connection.SimpleJdbcConnectionProvider)
    at com.funjoy.flink.ConfigSourceFunction.open(ConfigSourceFunction.java:52)
    at org.apache.flink.api.common.functions.util.FunctionUtils.openFunction(FunctionUtils.java:36)
    at org.apache.flink.streaming.api.operators.AbstractUdfStreamOperator.open(AbstractUdfStreamOperator.java:102)
    at org.apache.flink.streaming.runtime.tasks.OperatorChain.initializeStateAndOpenOperators(OperatorChain.java:291)
    at org.apache.flink.streaming.runtime.tasks.StreamTask.lambda$beforeInvoke$1(StreamTask.java:506)
    at org.apache.flink.streaming.runtime.tasks.StreamTask$$Lambda$617/1628357580.run(Unknown Source)
    at org.apache.flink.streaming.runtime.tasks.StreamTaskActionExecutor$SynchronizedStreamTaskActionExecutor.runThrowing(StreamTaskActionExecutor.java:92)
    - locked <0x00000007db8a37a0> (a java.lang.Object)
    at org.apache.flink.streaming.runtime.tasks.StreamTask.beforeInvoke(StreamTask.java:475)
    at org.apache.flink.streaming.runtime.tasks.StreamTask.invoke(StreamTask.java:526)
    at org.apache.flink.runtime.taskmanager.Task.doRun(Task.java:721)
    at org.apache.flink.runtime.taskmanager.Task.run(Task.java:546)
    at java.lang.Thread.run(Thread.java:748)

定位问题

从上面的堆栈来看和 waring 的信息一样, 可以确认线程确实卡在这了

而且是和 clickhouse 连接有关系

猜测: clickhouse-jdbc 连接库的问题

将 clickhouse-jdbc:0.2.4 升级到 clickhouse-jdbc:0.2.6 后故障依旧

既然不是 clickhouse 库的问题, 那就再往上一层看看

查看 SimpleJdbcConnectionProvider 的类是 flink-connector-jdbc 包中定义

这个包是和 flink 的版本保持一致的, 所以直接将 flink 从 1.11.3 升级到 1.12.1

测试了十几次都表现正常, 应该就是这个问题了

在github上找到 flink 1.12.1 版本的 SimpleJdbcConnectionProvider 变更记录

发现确实有这个 bug, 已经有大佬修复了这个问题.

至此整个故障问题已经确认

总结

一开始应该关注日志方面, 但是研发一直纠结是配置和环境的问题
所以在配置和环境上花费了很多时间.

对 java 不太熟悉, 从日志中的两个 waring 应该能定位到问题.

故障表现起来有一定的随机性, 所有验证起来很浪费时间