Impala查询卡顿分析案例

发布日期:2020-12-25 15:19
微信图片_20201211140659
Hadoop123:知名的大数据中台技术分享基地,涉及大数据架构(hadoop/spark/flink等),数据平台(数据交换、数据服务、数据治理等)和数据产品(BI、AB测试平台)等,也会分享最新技术进展,大数据相关职位和求职信息,大数据技术交流聚会、讲座以及会议等。

在开发时遇到查询卡顿(stuck)的情况,感觉比较有代表性,因此记录一下排查过程。在生产环境中也可以用类似的方法找到卡顿的源头。
注:本文所用的Impala版本为3.4.0-SNAPSHOT。Impala由C++和Java写成,分别对应BE (Backend) 和 FE (Frontend) 两部分。

案例描述:
使用Alter Table语句新建一个partition时,查询一直不返回。在Coordinator网页上可以看到查询一直处于CREATED状态,且持续长达十几分钟:

这个查询设置了 sync_ddl=true,在忙碌的集群里是有可能十几分钟未完成的,但在我的测试环境里就不应该这样。
Alter Table Add Partition语句属于DDL,设置sync_ddl=true时,其执行流程如下:

图中各个步骤如下:
(1) 客户端发送查询请求
(2) Coordinator向Catalogd发送ExecDdl请求
(3) Catalogd向HMS发送AddPartition请求
(4) HMS创建Partition,并在HDFS中创建partition目录
(5) Catalogd向NameNode加载新Partition的文件信息
(6) Catalogd在执行完DDL后,将元数据的更新发送给Statestore。Statestore会将更新广播给所有Coordinator。
(7) Catalogd返回包含更新的topic version给Coordinator
(8) Coordinator等到所有Coordinator都接收到了该version的更新时再返回给客户端

卡顿可能发生在上面任何一步中,需要从头开始排查。

查找卡顿源头
I. 找到Coordinator卡住的线程
查询是发给Coordinator的,因此从它开始。先查日志,找到这个查询相关的log。每个查询在被解析的时候都会打一行 “Analyzing ...” 这样的日志。

我的查询是 "ALTER TABLE insert_inherit_permission ADD PARTITION(p1=1, p2=1, p3=1)",在grep的时候可以加上些关键字快速定位。在我的测试环境中,日志是在 /tmp/impalad_node2.INFO,一般在CDH集群中,日志是在 /var/log/impalad/impalad.INFO。

日志中第三列就是线程id,因此FE处理这个查询的线程id是20747。可以看下这个线程所有的log,看到最后是停在 "Analysis and authorization finished":

既然已经做完语义分析和权限鉴定了,查询是卡在哪里呢?

先通过 jstack 看是否有相关信息,jstack输出中的nid就是十六进制的线程id,在我的例子中并没有发现线程20747的堆栈,因此要查看所有BE的线程了。BE是C++写的,理论上我们可以通过gdb attach上impalad,然后打出线程堆栈。但这样会停住整个impalad进程,可能会导致心跳超时而查询被取消的情况。为了不污染现场环境,可以使用gcore触发一次core dump。

Dump的时候会被形如 "[New LWP xxxxx]" 的输出刷屏,还可能会有warning,但不用管,只要最后是成功的就行了。生成的core文件一般会比较大,因为把进程的内存也dump下来了。比如在我的开发环境中,core文件就有12GB。

生产环境中的内存可能会更大,仍用core dump就不太合适了,后面我们再介绍其它的办法。有了core文件后,就可以用gdb来分析了。可能会占用大量内存,因此在生产环境中最好换台机器做分析。

找到线程20747并查看堆栈,gdb里的线程编号并不是线程id,但thread指令只能跳到指定编号的线程,因此我们要先用 "thread find 20747" 找到线程编号,然后再切到那个线程用bt指令打印堆栈。

输出的结果会比较长,如图所示:
所以Coordinator是向Catalogd发了RPC请求,正在等待结果返回。堆栈里有代码行号,也可查看相关代码。
现在可以确认Coordinator是卡在RPC上了,接下来需要确认Catalogd在做什么。

II. 找到Catalogd卡住的线程
Catalogd的日志里并没有发现明显的问题,还是得看线程堆栈。
源头就是卡在FE的 CatalogServiceCatalog.waitForSyncDdlVersion() 里,线程id是0x510c,也就是20748. 回看日志,最后一行输出是 "Loaded file and block metadata for ..."

因此该表的metadata加载已经完成了,进入waitForSyncDdlVersion是因为该查询使用了sync_ddl=true,catalogd需要等到更新被发送出去才能知道对应的statestore topic version,才能返回给coordinator。关于metadata的广播及sync_ddl的实现篇幅较长,我们在后续的文章中再介绍。

到此我的诊断就结束了,可以结合代码去debug。然而在生产环境中catalogd一般很忙碌,不一定能直接锁定jstack中的线程。有一个想法是通过coordinator线程确定跟catalogd连接的端口,再以此找到catalogd对应的线程,但fd是所有线程共享的,并没法通过端口来找到线程。因此目前也没有比较好的办法,好在catalogd的大部分逻辑都是java实现的,可以多打几次jstack,对比看哪些线程一直存在来排查。

使用Minidump替代Core Dump
生产环境中的impalad内存一般会比较大,如果使用core dump,生成的core文件也会很大,不利于分析。实际上我们感兴趣的是各个线程的堆栈,并不需要所有的内存数据。Google Breakpad 提供的 Minidumps 提供了新的解决方案,它只会导出崩溃原因、各个线程不超过8KB的栈内存、运行环境(OS、CPU等)和进程信息(加载的模块等)。这样导出的 Minidump 文件就非常小,在本例中,core dump文件的大小是 12GB,minidump 文件的大小却只有 3MB!

使用要求
  • Impala版本不低于2.7:Impala 2.7(对应的CDH版本是cdh5.9)开始支持外界触发的Minidump,只需要给进程发送SIGUSR1信号。
  • 编译对应版本的Impala源码:需要使用 Debug 模式编译才能保留所有符号信息(symbol),还需要使用toolchain中的breakpad工具来处理minidump。另外编译环境要跟线上环境一致,比如线上环境为ubuntu16.04,编译时也要找ubuntu16.04的机器来做。关于如何编译,可参考文档:https://cwiki.apache.org/confluence/display/IMPALA/Building+Impala

使用方法

1. 生成Minidump

找到impalad进程的PID,我这里是19731,然后用 "kill -s SIGUSR1 19731" 触发Minidump,成功后在impalad的日志中能找到生成的路径

2. 生成符号信息
Minidump文件并不包含任何符号信息,因此我们要自己生成Breakpad形式的符号信息来匹配上,这样我们才能看到函数名(而不只是函数地址)等等。

在编译Impala的目录(下称IMPALA_HOME)里,可以找到 bin/dump_breakpad_symbols.py,用它来生成breakpad形式的符号信息,假设说我们希望把符号信息存到 /tmp/syms,生成的文件大小是421MB,比Minidump文件还大一些,因为里面有各种文件名、函数名等。

3. 解析Minidump
使用Impala toolchain里的breakpad工具,假设对应的版本是 IMPALA_BREAKPAD_VERSION。中间会有刷屏的输出,只要最终解析成功就行了。
是OS、CPU等环境信息,然后就是各个线程的堆栈信息,每个堆栈的各个寄存器值也都显示出来了。第一个线程是breakpad做minidump的线程,因为Crash reason是DUMP_REQUESTED(实际上进程还活着,并没有crash)。如果是在线上环境进程崩溃,则第一个线程会是导致崩溃的线程。
回到Coordinator卡顿的分析,我们先是从日志找到了线程id为20747。
可惜breakpad并没有打出像gdb一样的LWP信息,线程的编号也跟gdb的不一样。但据观察,线程id(即LWP id)一般会出现在线程堆栈里前几个调用的寄存器里,经常可以借此找到线程。比如我们关心的线程id是20747,转换成16进制就是510b,在输出文件 /tmp/resolved.txt 里搜510b,刚好只有一个线程其堆栈里前几个调用的寄存器rbx值为 0x000000000000510b,而这个线程的堆栈也正就是 ExecDdl 的堆栈。
堆栈里同时也有代码的行号,感兴趣的朋友可以下载整个 resolved.txt 文件 (压缩后73KB) 研究研究:https://github.com/stiga-huang/BlogFiles/blob/master/Debugging%20on%20Stuck%20Query/resolved.txt.gz
在这之后就知道Coordinator是卡在等待ExecDdl的RPC返回了,后面同样可以对catalogd做分析。

总结

Impalad查询卡顿时,如果日志中无法发现异常,对于BE部分可以使用core dump或minidump来做线程堆栈分析,对于FE部分可以用jstack做分析。日志中的线程id对应gdb中的 LWP id 和 jstack 中的 nid (16进制),在minidump中找不到明显对应,可试图在寄存器值中匹配线程。
(注:BE是指Backend,主要是Impala的C++部分;FE是指Frontend,主要是Impala的Java部分)

指令回顾

  • gcore [-o filename] pid
  • gdb -c core_file program_binary
  • gdb指令
    • thread find thread_id (查找对应线程id在gdb中的线程编号)
    • thread id (跳到对应编号的线程)
    • bt (打印堆栈)
  • jstack pid
  • kill -s SIGUSR1 pid (触发impala进程生成minidump)
  • $IMPALA_HOME/bin/dump_breakpad_symbols.py -f binaries -d output_symbol_dir (生成Breakpad形式的符号文件)
  • $IMPALA_TOOLCHAIN/breakpad-$IMPALA_BREAKPAD_VERSION/bin/minidump_stackwalk $MINIDUMP_FILE $BREAKPAD_SYMBOLS > $RESULT_FILE (解析Minidump)

参考文档

  • https://cwiki.apache.org/confluence/display/IMPALA/Debugging+Impala+Core+Dumps+on+Another+System
  • https://cwiki.apache.org/confluence/display/IMPALA/Debugging+Impala+Minidumps
  • https://cwiki.apache.org/confluence/display/IMPALA/Building+Impala
 
分享到:
推荐精彩博文