Impala查询卡顿分析案例

微信图片_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
 
分享到：