作者：周鹏辉
文档编写目的
本文描述了在一次TPC-DS测试中，使用Impala对原始10TB的parquet格式表数据，使用snappy压缩后4.2TB数据进行查询时，出现The service queue contains 0 items out of a maximum of 2147483647; memory consumption is 50.59 MB.atement: 异常的分析和处理。
- 文档概述
1.异常描述
2.异常分析
3.异常解决
4.问题总结
- 测试环境
1.CDH and CM version：CDP7.1.1 and CM7.1.1
2.Impala version：impala 3.4.0
3.集群未启用Kerbeos OpenLDAP Sentry
异常描述
1.在一次TPC-DS的测试中，需要使用impala的五个并发来读取使用snappy压缩后的4.2TB parquet格式表数据（未压缩前为10TB），五条query 语句分别为q1.sql-q5.sql，执行的语句略。
2.当并发执行5条查询语句的时候，有时候只可以同时执行3个并发、有时候是2个并发、有时候是1个并发，其余的query就无法执行，失败的query日志看到如下异常：
代码语言：javascript复制Sql St Cancel() RPC failed: Remote error: Service unavailable: CancelQueryFInstances request on impala.ControlService from 172.16.8.30:55692 dropped due to backpressure. The service queue contains 0 items out of a maximum of 2147483647; memory consumption is 50.48 MB
3. impala现在配置:
异常分析
1.通过查了Impala的代码，出现这种报错一般是由于两种情况造成：
1）、一种情况是可用内存不足；
2）、另一种情况是impala service pool已经满了。
首先排查原因1）:
前期的猜测是由于并发执行查询导致impala daemon或者资源池里的内存不够了。理由是错误代码里显示的只是这一个调用所需要的内存，并不能反映出当时impalad里已经使用了多少内存以及还剩下多少可用内存。基于现在的理解，应该是impala daemon进程里预先分配的内存不足。所以尝试在CM上把Impala Daemon Memory Limit调高,并且设置查询的MEM_LIMIT避免这些查询把进程里的内存都消耗光。看这种方式能否避免出现 request “dropped due to backpressure”
2.进行如下配置修改和执行脚本：
1）、把集群Impala Daemon Memory Limit设置为288GB
2）、五个query 语句中set mem_limit=50000000000（5GB）再次进行测试,
3）、执行五个并发query
查看set mem_limit=50000000000已经生效
4)、但是还是出现和之前相同的异常，其中一个query运行在coordinator：testcdhdn03
3.通过对当时运行的5个query[1]中的profile文件和对应的impala deamon日志分析:
代码语言：javascript复制testcdhdn01 28418d0306dba6d2:31a1373b00000000
testcdhdn02 534d1dae8e9c5ccb:83d8970100000000
testcdhdn03 0d45d36163061878:d0760e3600000000
testcdhdn04 0e4138beaca7ceab:e28d13a800000000
testcdhdn05 b54a57266ca8a7ce:5cbb99c300000000
1)、 从profile里的timeline来看，发现coordinator比较慢[2]。从JVM里编译完查询之后花了很长的时间才完成scheduling和admission。而且有两个profile里有 Admission control state staleness: Warning: admission control information from statestore is stale: 23s100ms since last update was received.” [3]“的警告。Query Compilation是在JVM里采集的指标，而Query Timeline是在C 代码里采集的指标。看到在JVM里这个查询在2.74秒就已经编译完了，但是在C 代码里13.13秒才收到查询编译的结果。按道理C 代码调用Java代码完成编译之后应该可以立即收到结果，但是以上有11秒左右的延时。这个显得有些不太正常。所以怀疑是当时的线程数太多了导致CPU在调度上有延时。
[2]
代码语言：javascript复制Query Compilation
...
Planning finished: 2.74秒 (2739947754)
Query Timeline
Query submitted: 1毫秒 (1000009)
Planning finished: 13.13秒 (13126121462)
[3]
profile-q1-Coordinator-testcdhdn01.txt:
profile-q2-Coordinator-testcdhdn02.txt:
2)、多个节点上出现了线程卡在内核里的现象[4]。在testcdhdn01节点上出现得尤其多
[4]
代码语言：javascript复制W0831 17:49:34.846180 227939 kernel_stack_watchdog.cc:198] Thread 227969 stuck at outbound_call.cc:273 for 279ms:
Kernel stack:
[<ffffffff810f5126>] futex_wait_queue_me 0xc6/0x130
[<ffffffff810f5deb>] futex_wait 0x17b/0x280
[<ffffffff810f7b26>] do_futex 0x106/0x5a0
3）、这个查询有多达411个fragment[5]，在每个节点上有91个fragment instances[6]。每个instance都会创建几个线程。5个查询并发执行的时候在每个impalad进程里会产生大约2000个线程，而这些imapalad节点上的CPU内核是36vcore个。在36个vcore上调度2000个线程所带来的额外开销是很大的。这可能是造成1）和2）的原因。
这里涉及到每个query的“Plan fragment ”、“Fragment Instances”、每个instance创建了多个线程在impala是如何预估的问题。实际上我们无法从日志或者profile里看到每个instance创建了多少个线程。一般来说，我们可以认为一个instance有三个线程，主处理线程和数据收/发线程。但是有的时候instance创建的线程会更多一些。理想情况下，每个CPU内核处理一个活跃的线程而其他的线程都处于等待状态。问题是我们很难判断一个查询里有多少个线程在某个时间点是活跃的，所以我们只能通过观察来判断。
[5]
代码语言：javascript复制F411:PLAN FRAGMENT [UNPARTITIONED] hosts=1 instances=1
[6]
4)、impalad进程的mem_limit设置为288G。在CDP中默认情况下85%能够用于buffer pool。也就是说所有pool里在一个节点上同时最多能够使用244.8G内存。而这5个查询设置的MEM_LIMIT是5G。那么5个查询同时执行的话在一个节点上只需要25GB内存。就算各个节点上的内存使用统计同步有延时再加上前面3.1）coordinator比较慢的原因，也没有达到内存不足而报错终止的条件。
这里涉及到impalad各个节点上的内存使用统计同步有延时的问题。因为各个节点上的内存使用情况是通过statestored同步的。而statestored是通过轮询的方式从各个impalad采集内存使用情况。因此实际上的内存使用统计有一定程度上的延时。默认情况下的轮询间隔时间是100毫秒[7].
[7]
代码语言：javascript复制https://github.com/cloudera/Impala/blob/495397101e5807c701df71ea288f4815d69c2c8a/be/src/statestore/statestore.cc#L72
6. 于是我们尝试从server pool层面排查问题。通过再次查找资料，发现从CDH6.2.0开始引进了一个新的impalad命令行参数control_service_queue_mem_limit。这个参数的默认值是50MB。其目的是把执行查询时的控制命令从原来的数据流里剥离出来，从而避免不必要的延时甚至阻塞。我们测试的查询应该是因为有很多的fragment所以RPC调用很多从而超出了50MB的限制。所以尝试在Impala daemon命令行参数里把control_service_queue_mem_limit设置成100MB再看看。
异常解决
1.按照如下操作设置control_service_queue_mem_limit为100MB.
1）打开CM，跳转到Clusters -> Impala service -> Configuration页面；
2）搜索 Impala Daemon Command Line Argument Advanced Configuration Snippet (Safety Valve)，中文是 “Impala Daemon 命令行参数高级配置代码段（安全阀）”
3）添加如下一行设置control_service_queue_mem_limit为100MB
代码语言：javascript复制--control_service_queue_mem_limit=100
4）保存设置，重启服务。
2.再次并发执行5个query
五个query都执行完成
测试脚本和日志如下：
问题总结
1.此问题的根本原因是测试的查询因为有很多的fragment所以RPC调用很多从而超出了control_service_queue_mem_limit 为50MB的限制，导致service pool的延迟；
2. 参数control_service_queue_mem_limit是在IMPALA-7213, IMPALA-7241[1]里引入的，CDH6.2.0中加入了此参数。这次修改引入了sevice pool，其目的是把执行查询时的控制命令从原来的数据流里剥离出来，从而避免不必要的延时甚至阻塞。关于此参参数的代码可以参见[2]
[1]
代码语言：javascript复制https://github.com/apache/impala/commit/5391100c7eeb33193de7861e761c3920f1d1eecc
https://issues.apache.org/jira/browse/IMPALA-7213
https://issues.apache.org/jira/browse/IMPALA-7241
[2]
代码语言：javascript复制https://github.com/cloudera/Impala/blob/495397101e5807c701df71ea288f4815d69c2c8a/be/src/service/control-service.cc#L48
3. impalad进程的mem_limit设置为288G，在CDP中默认情况下85%能够用于buffer pool.这个参数比例在不同的版本里发生过变化。比如在CDH5.13.x中就是80%。在CDH6.1.1里已经变成了85%。可以从代码[3]里看到。这个变动的原因是一些以前不被buffer pool管理的内存也被纳入到了buffer pool中，所以这个比例被提升了。
[3]
代码语言：javascript复制https://github.com/cloudera/Impala/blob/495397101e5807c701df71ea288f4815d69c2c8a/be/src/common/global-flags.cc#L69
