写点什么

Flink Checkpoint 问题排查实用指南

  • 2019-09-19
  • 本文字数:5312 字

    阅读完需:约 17 分钟

Flink Checkpoint问题排查实用指南

在 Flink 中,状态可靠性保证由 Checkpoint 支持,当作业出现 failover 的情况下,Flink 会从最近成功的 Checkpoint 恢复。在实际情况中,我们可能会遇到 Checkpoint 失败,或者 Checkpoint 慢的情况,本文会统一聊一聊 Flink 中 Checkpoint 异常的情况(包括失败和慢),以及可能的原因和排查思路。

1. Checkpoint 流程简介

首先我们需要了解 Flink 中 Checkpoint 的整个流程是怎样的,在了解整个流程之后,我们才能在出问题的时候,更好的进行定位分析。



从上图我们可以知道,Flink 的 Checkpoint 包括如下几个部分:


  • JM trigger checkpoint

  • Source 收到 trigger checkpoint 的 PRC,自己开始做 snapshot,并往下游发送 barrier

  • 下游接收 barrier(需要 barrier 都到齐才会开始做 checkpoint)

  • Task 开始同步阶段 snapshot

  • Task 开始异步阶段 snapshot

  • Task snapshot 完成,汇报给 JM


上面的任何一个步骤不成功,整个 checkpoint 都会失败。

2 Checkpoint 异常情况排查

2.1 Checkpoint 失败

可以在 Checkpoint 界面看到如下图所示,下图中 Checkpoint 10423 失败了。



点击 Checkpoint 10423 的详情,我们可以看到类系下图所示的表格(下图中将 operator 名字截取掉了)。



上图中我们看到三行,表示三个 operator,其中每一列的含义分别如下:


  • 其中 Acknowledged 一列表示有多少个 subtask 对这个 Checkpoint 进行了 ack,从图中我们可以知道第三个 operator 总共有 5 个 subtask,但是只有 4 个进行了 ack;

  • 第二列 Latest Acknowledgement 表示该 operator 的所有 subtask 最后 ack 的时间;

  • End to End Duration 表示整个 operator 的所有 subtask 中完成 snapshot 的最长时间;

  • State Size 表示当前 Checkpoint 的 state 大小 – 主要这里如果是增量 checkpoint 的话,则表示增量大小;

  • Buffered During Alignment 表示在 barrier 对齐阶段积攒了多少数据,如果这个数据过大也间接表示对齐比较慢);


Checkpoint 失败大致分为两种情况:Checkpoint Decline 和 Checkpoint Expire。

2.1.1 Checkpoint Decline

我们能从 jobmanager.log 中看到类似下面的日志


Decline checkpoint 10423 by task 0b60f08bf8984085b59f8d9bc74ce2e1 of job 85d268e6fbc19411185f7e4868a44178. 其中


10423 是 checkpointID,0b60f08bf8984085b59f8d9bc74ce2e1 是 execution id,85d268e6fbc19411185f7e4868a44178 是 job id,我们可以在 jobmanager.log 中查找 execution id,找到被调度到哪个 taskmanager 上,类似如下所示:


2019-09-02 16:26:20,972 INFO  [jobmanager-future-thread-61] org.apache.flink.runtime.executiongraph.ExecutionGraph        - XXXXXXXXXXX (100/289) (87b751b1fd90e32af55f02bb2f9a9892) switched from SCHEDULED to DEPLOYING.2019-09-02 16:26:20,972 INFO  [jobmanager-future-thread-61] org.apache.flink.runtime.executiongraph.ExecutionGraph        - Deploying XXXXXXXXXXX (100/289) (attempt #0) to slot container_e24_1566836790522_8088_04_013155_1 on hostnameABCDE
复制代码


从上面的日志我们知道该 execution 被调度到 hostnameABCDEcontainer_e24_1566836790522_8088_04_013155_1 slot 上,接下来我们就可以到 container container_e24_1566836790522_8088_04_013155 的 taskmanager.log 中查找 Checkpoint 失败的具体原因了。


另外对于 Checkpoint Decline 的情况,有一种情况我们在这里单独抽取出来进行介绍:Checkpoint Cancel。


当前 Flink 中如果较小的 Checkpoint 还没有对齐的情况下,收到了更大的 Checkpoint,则会把较小的 Checkpoint 给取消掉。我们可以看到类似下面的日志:


$taskNameWithSubTaskAndID: Received checkpoint barrier for checkpoint 20 before completing current checkpoint 19. Skipping current checkpoint.
复制代码


这个日志表示,当前 Checkpoint 19 还在对齐阶段,我们收到了 Checkpoint 20 的 barrier。然后会逐级通知到下游的 task checkpoint 19 被取消了,同时也会通知 JM 当前 Checkpoint 被 decline 掉了。


在下游 task 收到被 cancelBarrier 的时候,会打印类似如下的日志:


DEBUG$taskNameWithSubTaskAndID: Checkpoint 19 canceled, aborting alignment.
或者
DEBUG$taskNameWithSubTaskAndID: Checkpoint 19 canceled, skipping alignment.
或者
WARN$taskNameWithSubTaskAndID: Received cancellation barrier for checkpoint 20 before completing current checkpoint 19. Skipping current checkpoint.
复制代码


上面三种日志都表示当前 task 接收到上游发送过来的 barrierCancel 消息,从而取消了对应的 Checkpoint。

2.1.2 Checkpoint Expire

如果 Checkpoint 做的非常慢,超过了 timeout 还没有完成,则整个 Checkpoint 也会失败。当一个 Checkpoint 由于超时而失败是,会在 jobmanager.log 中看到如下的日志:


Checkpoint 1 of job 85d268e6fbc19411185f7e4868a44178  expired before completing.
复制代码


表示 Chekpoint 1 由于超时而失败,这个时候可以可以看这个日志后面是否有类似下面的日志:


Received late message for now expired checkpoint attempt 1 from 0b60f08bf8984085b59f8d9bc74ce2e1 of job 85d268e6fbc19411185f7e4868a44178.
复制代码


可以按照 2.1.1 中的方法找到对应的 taskmanager.log 查看具体信息。


下面的日志如果是 DEBUG 的话,我们会在开始处标记 DEBUG


我们按照下面的日志把 TM 端的 snapshot 分为三个阶段,开始做 snapshot 前,同步阶段,异步阶段:


DEBUGStarting checkpoint (6751) CHECKPOINT on task taskNameWithSubtasks (4/4)
复制代码


这个日志表示 TM 端 barrier 对齐后,准备开始做 Checkpoint。


DEBUG2019-08-06 13:43:02,613 DEBUG org.apache.flink.runtime.state.AbstractSnapshotStrategy       - DefaultOperatorStateBackend snapshot (FsCheckpointStorageLocation {fileSystem=org.apache.flink.core.fs.SafetyNetWrapperFileSystem@70442baf, checkpointDirectory=xxxxxxxx, sharedStateDirectory=xxxxxxxx, taskOwnedStateDirectory=xxxxxx, metadataFilePath=xxxxxx, reference=(default), fileStateSizeThreshold=1024}, synchronous part) in thread Thread[Async calls on Source: xxxxxx_source -> Filter (27/70),5,Flink Task Threads] took 0 ms.
复制代码


上面的日志表示当前这个 backend 的同步阶段完成,共使用了 0 ms。


DEBUGDefaultOperatorStateBackend snapshot (FsCheckpointStorageLocation {fileSystem=org.apache.flink.core.fs.SafetyNetWrapperFileSystem@7908affe, checkpointDirectory=xxxxxx, sharedStateDirectory=xxxxx, taskOwnedStateDirectory=xxxxx,  metadataFilePath=xxxxxx, reference=(default), fileStateSizeThreshold=1024}, asynchronous part) in thread Thread[pool-48-thread-14,5,Flink Task Threads] took 369 ms
复制代码


上面的日志表示异步阶段完成,异步阶段使用了 369 ms


在现有的日志情况下,我们通过上面三个日志,定位 snapshot 是开始晚,同步阶段做的慢,还是异步阶段做的慢。然后再按照情况继续进一步排查问题。

2.2 Checkpoint 慢

在 2.1 节中,我们介绍了 Checkpoint 失败的排查思路,本节会分情况介绍 Checkpoint 慢的情况。


Checkpoint 慢的情况如下:比如 Checkpoint interval 1 分钟,超时 10 分钟,Checkpoint 经常需要做 9 分钟(我们希望 1 分钟左右就能够做完),而且我们预期 state size 不是非常大。


对于 Checkpoint 慢的情况,我们可以按照下面的顺序逐一检查

2.2.0 Source Trigger Checkpoint 慢

这个一般发生较少,但是也有可能,因为 source 做 snapshot 并往下游发送 barrier 的时候,需要抢锁(这个现在社区正在进行用 mailBox 的方式替代当前抢锁的方式,详情参考[1])。如果一直抢不到锁的话,则可能导致 Checkpoint 一直得不到机会进行。如果在 Source 所在的 taskmanager.log 中找不到开始做 Checkpoint 的 log,则可以考虑是否属于这种情况,可以通过 jstack 进行进一步确认锁的持有情况。

2.2.1 使用增量 Checkpoint

现在 Flink 中 Checkpoint 有两种模式,全量 Checkpoint 和 增量 Checkpoint,其中全量 Checkpoint 会把当前的 state 全部备份一次到持久化存储,而增量 Checkpoint,则只备份上一次 Checkpoint 中不存在的 state,因此增量 Checkpoint 每次上传的内容会相对更好,在速度上会有更大的优势。


现在 Flink 中仅在 RocksDBStateBackend 中支持增量 Checkpoint,如果你已经使用 RocksDBStateBackend,可以通过开启增量 Checkpoint 来加速,具体的可以参考 [2]。

2.2.2 作业存在反压或者数据倾斜

我们知道 task 仅在接受到所有的 barrier 之后才会进行 snapshot,如果作业存在反压,或者有数据倾斜,则会导致全部的 channel 或者某些 channel 的 barrier 发送慢,从而整体影响 Checkpoint 的时间,这两个可以通过如下的页面进行检查:



上图中我们选择了一个 task,查看所有 subtask 的反压情况,发现都是 high,表示反压情况严重,这种情况下会导致下游接收 barrier 比较晚。



上图中我们选择其中一个 operator,点击所有的 subtask,然后按照 Records Received/Bytes Received/TPS 从大到小进行排序,能看到前面几个 subtask 会比其他的 subtask 要处理的数据多。


如果存在反压或者数据倾斜的情况,我们需要首先解决反压或者数据倾斜问题之后,再查看 Checkpoint 的时间是否符合预期。

2.2.2 Barrier 对齐慢

从前面我们知道 Checkpoint 在 task 端分为 barrier 对齐(收齐所有上游发送过来的 barrier),然后开始同步阶段,再做异步阶段。如果 barrier 一直对不齐的话,就不会开始做 snapshot。


barrier 对齐之后会有如下日志打印:


DEBUGStarting checkpoint (6751) CHECKPOINT on task taskNameWithSubtasks (4/4)
复制代码


如果 taskmanager.log 中没有这个日志,则表示 barrier 一直没有对齐,接下来我们需要了解哪些上游的 barrier 没有发送下来,如果你使用 At Least Once 的话,可以观察下面的日志:


DEBUGReceived barrier for checkpoint 96508 from channel 5
复制代码


表示该 task 收到了 channel 5 来的 barrier,然后看对应 Checkpoint,再查看还剩哪些上游的 barrier 没有接受到,对于 ExactlyOnce 暂时没有类似的日志,可以考虑自己添加,或者 jmap 查看。

2.2.3 主线程太忙,导致没机会做 snapshot

在 task 端,所有的处理都是单线程的,数据处理和 barrier 处理都由主线程处理,如果主线程在处理太慢(比如使用 RocksDBBackend,state 操作慢导致整体处理慢),导致 barrier 处理的慢,也会影响整体 Checkpoint 的进度,在这一步我们需要能够查看某个 PID 对应 hotmethod,这里推荐两个方法:


  1. 多次连续 jstack,查看一直处于 RUNNABLE 状态的线程有哪些;

  2. 使用工具 AsyncProfile dump 一份火焰图,查看占用 CPU 最多的栈;


如果有其他更方便的方法当然更好,也欢迎推荐。

2.2.4 同步阶段做的慢

同步阶段一般不会太慢,但是如果我们通过日志发现同步阶段比较慢的话,对于非 RocksDBBackend 我们可以考虑查看是否开启了异步 snapshot,如果开启了异步 snapshot 还是慢,需要看整个 JVM 在干嘛,也可以使用前一节中的工具。对于 RocksDBBackend 来说,我们可以用 iostate 查看磁盘的压力如何,另外可以查看 tm 端 RocksDB 的 log 的日志如何,查看其中 SNAPSHOT 的时间总共开销多少。


RocksDB 开始 snapshot 的日志如下:


2019/09/10-14:22:55.734684 7fef66ffd700 [utilities/checkpoint/checkpoint_impl.cc:83] Started the snapshot process -- creating snapshot in directory /tmp/flink-io-87c360ce-0b98-48f4-9629-2cf0528d5d53/XXXXXXXXXXX/chk-92729
复制代码


snapshot 结束的日志如下:


2019/09/10-14:22:56.001275 7fef66ffd700 [utilities/checkpoint/checkpoint_impl.cc:145] Snapshot DONE. All is good
复制代码

2.2.6 异步阶段做的慢

对于异步阶段来说,tm 端主要将 state 备份到持久化存储上,对于非 RocksDBBackend 来说,主要瓶颈来自于网络,这个阶段可以考虑观察网络的 metric,或者对应机器上能够观察到网络流量的情况(比如 iftop)。


对于 RocksDB 来说,则需要从本地读取文件,写入到远程的持久化存储上,所以不仅需要考虑网络的瓶颈,还需要考虑本地磁盘的性能。另外对于 RocksDBBackend 来说,如果觉得网络流量不是瓶颈,但是上传比较慢的话,还可以尝试考虑开启多线程上传功能[3]。

3 总结

在第二部分内容中,我们介绍了官方编译的包的情况下排查一些 Checkpoint 异常情况的主要场景,以及相应的排查方法,如果排查了上面所有的情况,还是没有发现瓶颈所在,则可以考虑添加更详细的日志,逐步将范围缩小,然后最终定位原因。


上文提到的一些 DEBUG 日志,如果 flink dist 包是自己编译的话,则建议将 Checkpoint 整个步骤内的一些 DEBUG 改为 INFO,能够通过日志了解整个 Checkpoint 的整体阶段,什么时候完成了什么阶段,也在 Checkpoint 异常的时候,快速知道每个阶段都消耗了多少时间。

参考内容

[1] Change threading-model in StreamTask to a mailbox-based approach


[2] 增量 checkpoint 原理介绍


[3] RocksDBStateBackend 多线程上传 State


2019-09-19 08:006835

评论 1 条评论

发布
用户头像
第三张图上面有一个错别字,麻烦修改下,"看到类系下图" --> "看到类似下图“
2019-09-21 14:14
回复
没有更多了
发现更多内容

Axure RP 11 for Mac永久激活码 附Axure RP 11 中文安装教程

Rose

HarmonyOS Next 自定义组件@Component的生命周期

auhgnixgnahz

鸿蒙Next

鸿蒙Next状态管理装饰器V2 @ObservedV2@Trace@Local

auhgnixgnahz

视觉特效 FxFactory 8 pro最新版 附fxfactory 破解补丁和安装教程

Rose

HarmonyOS Next常用组件 TextInput

auhgnixgnahz

鸿蒙Next

Archicad 28 mac破解安装教程+技术规格 专业的3D建筑建模工具

Rose

YashanDB数据库的未来发展趋势

数据库砖家

鸿蒙Next状态管理装饰器V2 @Param@Once@Event

auhgnixgnahz

鸿蒙Next

洞见未来:驱动零售业变革的5大关键趋势

第七在线

MyEMS核心代码解读001

开源能源管理系统

开源 能源管理 开源能源管理

苹果电脑 steam 游戏打不开怎么办?Mac 版的 steam 连接报错的原因及解决方案

阿拉灯神丁

MacBook crossover steam 如何在Mac上运行win游戏

MyEMS开源能源管理系统核心代码解读002

开源能源管理系统

开源 代码 能源管理 开源能源管理

YashanDB数据库的使用和管理中常见误区

数据库砖家

YashanDB数据库的事务及其一致性保障机制

数据库砖家

CST热仿真THs求解器--同轴连接器

思茂信息

cst CST软件 CST Studio Suite

强大的现场表演工具 Apple MainStage 3中文最新版

Rose

Mac简单好用的防火墙 LuLu详细使用安装教程

Rose

YashanDB数据库的数据模型灵活性与扩展方案

数据库砖家

手机和PC远控安全深度测评:TeamViewer/ToDesk/向日葵安全防线对比

小喵子

远程 向日葵 ToDesk TeamViewer 远程访问

YashanDB数据库的事务管理功能详细讲解

数据库砖家

YashanDB数据库的完整性约束与实现方法

数据库砖家

Speculative Decoding 推测解码方案详解

Se7en

搜索增强工具 HoudahSpot for Mac中文汉化资源 附HoudahSpot激活码

Rose

YashanDB数据库的时效性与数据更新策略如何设计?

数据库砖家

YashanDB数据库的实践教学与培训课程指导

数据库砖家

HarmonyOS Next Refresh+List实现下拉刷新上拉加载

auhgnixgnahz

Golang 反模式避坑实践

俞凡

golang 最佳实践

破局!揭秘“医药物流AI大模型”如何重塑供应链效率

极客天地

YashanDB数据库的事务管理与一致性保证机制

数据库砖家

YashanDB数据库的完整备份与恢复解决方案

数据库砖家

鸿蒙Next组件状态管理装饰器V1

auhgnixgnahz

Flink Checkpoint问题排查实用指南_AICon_邱从贤_InfoQ精选文章