翻译：九州暮云
作者：Eric Lin (林晨辉)， Cloudera高级售后技术支持工程师。毕业于Monash大学计算机科学， Sir John Monash的奖学金获得者。曾就业于数据收集公司如Hitwise（现为Experian的子公司）和Effective Measure，担任高级工程师，负责设计，开发和管理用于采集， 处理和报告网络数据的平台（基于PHP，Java和CDH）。现任职Cloudera， 担任高级售后技术支持工程师，主要擅长解决在CDH生态系统中出现的各种疑难杂症。
在本系列的第三部分，我使用了一个示例来详细地介绍Impala query profile。在这一部分中，我将使用一个真实生产系统的Impala Profile文件，解释我在遇到问题时阅读Profile文件的步骤，并逐渐找到引起问题的真正原因。如果你错过了我的文章的前3个部分，你可以点击以下链接阅读一下：
《一步一步理解Impala query profile（一）》
《一步一步理解Impala query profile（二）》
《一步一步理解 Impala query profile（三）》
好了，我们开始吧。由于Profile文件本身相当大，因为它涉及到多个Impalad进程，所以如果我将完整的内容在页面上显示出来，页面就会很难看。因此，请从以下链接下载，并在你本地电脑或浏览器上来查看这个文件。
代码语言：javascript复制https://www.ericlin.me/wp-content/uploads/2020/01/profile-example.txt这个查询的问题是，不知道出于什么原因，之前执行相同的查询几分钟内就可以完成，但现在要花1个多小时才能完成。这个Profile文件只是其中的一个例子，实际上，当时在这个集群中运行的所有查询都有相同的问题。所以请花点时间看一下这个Profile，看看你是否能获取什么有用的信息，并对问题产生的场景有一个大致的了解。
现在，让我们一起来看看排查该问题的步骤。
1、由于用户反馈查询时间比正常情况下长，我想知道的第一件事是到底花费了多长时间？所以首先，我在Profile的开头查看查询开始和结束的时间：
代码语言：javascript复制Start Time: 2020-01-03 07:33:42.928171000
End Time: 2020-01-03 08:47:55.745537000
我发现，现在完成查询需要1小时14分钟，这与用户的反馈是相符的。
2、由于用户取消，查询异常失败：
代码语言：javascript复制Query State: EXCEPTION
Query Status: Cancelled
用户已经没有耐心了，不得不取消查询，因为它运行了太长时间，这里没什么好担心的。
3、接下来，我检查了查询的复杂程度：
代码语言：javascript复制 Sql Statement:
SELECT COUNT(*),NVL(SUM(NVL(NUMBER_OF_CALLS,0)),0)
FROM cef_hpmn
WHERE settlement_month IN (
SELECT DISTINCT dd.month_id
FROM ext_call_event_fact cef, date_dim dd
WHERE CAST(settlement_date_id AS bigint) = dd.date_id
)
AND process_date = TO_TIMESTAMP ('01/02/2020', 'MM/dd/yyyy')
为了可读性，我重新格式化了。可以看到这个查询非常简单，是一个带有子查询条件的直接SELECT语句。
4、接下来我看到的是协调（Coordinator）节点的主机名称：
代码语言：javascript复制Coordinator: xxxxx-xxx-cdh-cdn003.xxx.XXXXXX.com:22000
如果我不能从这个Profile文件得出任何结论，那么下一步应该是获取这个主机上的impalad日志。但是现在，我只能继续，因为我还没有日志。
5、正如我在上一篇文章中提到的，Profile文件接下来的部分是查询计划（Query Plan），通常我会先跳过这部分，然后跳到概要（Summary）部分，以了解每个操作花了多长时间，并查看是否有什么明显的信息可能会让我有所发现：
代码语言：javascript复制Operator #Hosts Avg Time Max Time #Rows Est. #Rows Peak Mem Est. Peak Mem Detail
-----------------------------------------------------------------------------------------------------------
12:AGGREGATE 1 0.000ns 0.000ns 0 1 16.00 KB 10.00 MB FINALIZE
11:EXCHANGE 1 0.000ns 0.000ns 28 1 232.00 KB 0 UNPA...
06:AGGREGATE 29 61.358ms 110.536ms 28 1 13.60 MB 10.00 MB
05:HASH JOIN 29 223.055ms 345.295ms 277.41M 116.66M 2.00 MB 1.94 MB LEFT...
|--10:EXCHANGE 29 29.977us 67.789us 2 261 24.00 KB 0 BROADCAST
| 09:AGGREGATE 29 1.569ms 2.903ms 2 261 1.96 MB 10.00 MB FINALIZE
| 08:EXCHANGE 29 33.880us 419.580us 58 261 240.00 KB 0 HASH(..
| 04:AGGREGATE 29 9s751ms 3m53s 58 261 4.58 MB 10.00 MB STREAMING
| 03:HASH JOIN 29 1s099ms 2s635ms 411.27M 411.27M 3.35 MB 1.94 MB INNER ..
| |--07:EXCHANGE 29 142.532us 334.794us 8.07K 8.07K 304.00 KB 0 BROADCAST
| | 02:SCAN HDFS 1 1.700ms 1.700ms 8.07K 8.07K 332.94 KB 32.00 MB xx..
| 01:SCAN HDFS 29 44s391ms 13m18s 411.27M 411.27M 525.95 MB 4.38 GB xx..
00:SCAN HDFS 29 3m7s 56m13s 277.41M 116.66M 7.83 MB 160.00 MB xx..
我在这里找到了几个关键的信息：
- 反向阅读，从下到上，因为这是Impala的操作顺序
- 比较“Avg Time”和“Max Time”列的数据
- 比较“Rows”和“Est. #Rows”列的数据
- 检查“Detail”列以查看每个操作的Join类型
很快，我就注意到扫描HDFS（SCAN HDFS）操作的“Avg Time”和“Max Time”的差别很大，平均时间为3分7秒，但是29个主机中的一个主机的最长时间为56分13秒。继续往下读，我还注意到第二次扫描HDFS操作也有相同的问题，分别是44秒和13分18秒。
因此，我的下一个想法是确定哪些主机的执行速度比其他主机慢，以及是否来自同一主机。为此，我使用字符串“id=0”来搜索Profile文件，“0”是Summary部分“00:SCAN HDFS”中每一行开头的操作编号。
我从文件开头搜索到了“id=0”的第一部分：
代码语言：javascript复制 HDFS_SCAN_NODE (id=0)
....
- ScannerThreadsTotalWallClockTime: 20.0m (1200982115995)
- MaterializeTupleTime(*): 226ms (226568242)
- ScannerThreadsSysTime: 322ms (322168172)
- ScannerThreadsUserTime: 6.76s (6758158482)
- ScannerThreadsVoluntaryContextSwitches: 10,907 (10907)
- TotalRawHdfsOpenFileTime(*): 8.6m (517759170560)
- TotalRawHdfsReadTime(*): 3.4m (201957505069)
- TotalReadThroughput: 749.9 KiB/s (767874)
- TotalTime: 3.1m (187289950304)
我发现TotalTime为3.1分钟，与Summary部分中看到的3.7分钟相匹配，因此这是Averaged Fragment。为了确认，我向后滚动并看到以下内容：
代码语言：javascript复制Averaged Fragment F00
继续搜索文件，我来到下面部分(第二个实例“id=0”)：
代码语言：javascript复制 HDFS_SCAN_NODE (id=0)
....
- ScannerThreadsTotalWallClockTime: 10.4m (626435081910)
- MaterializeTupleTime(*): 278ms (278689886)
- ScannerThreadsSysTime: 266ms (266094000)
- ScannerThreadsUserTime: 5.75s (5748833000)
- ScannerThreadsVoluntaryContextSwitches: 11,285 (11285)
- TotalRawHdfsOpenFileTime(*): 7.8m (468388283839)
- TotalRawHdfsReadTime(*): 1.9m (114598713147)
- TotalReadThroughput: 731.0 KiB/s (748535)
- TotalTime: 2.1m (125005670562)
这个告诉我花了2.1分钟，比平均3.1分钟要快，然后我回滚到前面以确认主机：
代码语言：javascript复制 Fragment F00
Instance 94481a81355e51e4:51fd9f9500000053 (host=xxxxx-xxx-cdh-cdn002.xxx.XXXXXX.com:22000)
现在，可以看到我找到的三个主要信息：
代码语言：javascript复制 Instance 94481a81355e51e4:51fd9f9500000053 (host=xxxxx-xxx-cdh-cdn002.xxx.XXXXXX.com:22000)
HDFS_SCAN_NODE (id=0)
- TotalTime: 2.1m (125005670562)
接下来我使用grep过滤出我想要的内容。由于Profile文件已缩进，因此我使用egrep执行了下面的操作：
代码语言：javascript复制egrep ' Instance .*)|^ HDFS_SCAN_NODE (id=0)|^ - TotalTime: ' profile-example.txt
结果如下：
代码语言：javascript复制...
Instance 94481a81355e51e4:51fd9f9500000053 (host=xxxxx-xxx-cdh-cdn002.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 2.1m (125005670562)
Instance 94481a81355e51e4:51fd9f9500000057 (host=xxxxx-xxx-cdh-cdn003.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.9m (114395426955)
Instance 94481a81355e51e4:51fd9f9500000058 (host=xxxxx-xxx-cdh-cdn020.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.5m (92671503850)
Instance 94481a81355e51e4:51fd9f950000003d (host=xxxxx-xxx-cdh-cdn012.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.4m (86459970122)
Instance 94481a81355e51e4:51fd9f950000004b (host=xxxxx-xxx-cdh-cdn014.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.4m (82187347776)
Instance 94481a81355e51e4:51fd9f9500000050 (host=xxxxx-xxx-cdh-cdn006.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.4m (82146306944)
Instance 94481a81355e51e4:51fd9f950000004f (host=xxxxx-xxx-cdh-cdn024.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.3m (80468400288)
Instance 94481a81355e51e4:51fd9f950000004d (host=xxxxx-xxx-cdh-cdn022.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.3m (79714897965)
Instance 94481a81355e51e4:51fd9f9500000043 (host=xxxxx-xxx-cdh-cdn017.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.3m (78877950983)
Instance 94481a81355e51e4:51fd9f9500000052 (host=xxxxx-xxx-cdh-cdn001.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.3m (77593734314)
Instance 94481a81355e51e4:51fd9f950000003c (host=xxxxx-xxx-cdh-cdn019.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.3m (76164245478)
Instance 94481a81355e51e4:51fd9f9500000045 (host=xxxxx-xxx-cdh-cdn007.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.3m (75588331159)
Instance 94481a81355e51e4:51fd9f9500000044 (host=xxxxx-xxx-cdh-cdn010.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.2m (73596530464)
Instance 94481a81355e51e4:51fd9f9500000042 (host=xxxxx-xxx-cdh-cdn018.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.2m (72946574082)
Instance 94481a81355e51e4:51fd9f9500000055 (host=xxxxx-xxx-cdh-cdn026.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.2m (69918383242)
Instance 94481a81355e51e4:51fd9f9500000054 (host=xxxxx-xxx-cdh-cdn011.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.2m (69355611992)
Instance 94481a81355e51e4:51fd9f9500000051 (host=xxxxx-xxx-cdh-cdn009.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.1m (68527129814)
Instance 94481a81355e51e4:51fd9f9500000048 (host=xxxxx-xxx-cdh-cdn016.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.1m (67249633571)
Instance 94481a81355e51e4:51fd9f9500000047 (host=xxxxx-xxx-cdh-cdn013.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.1m (63989781076)
Instance 94481a81355e51e4:51fd9f9500000041 (host=xxxxx-xxx-cdh-cdn028.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.0m (62739870946)
Instance 94481a81355e51e4:51fd9f950000003f (host=xxxxx-xxx-cdh-cdn025.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.0m (62136511127)
Instance 94481a81355e51e4:51fd9f950000004c (host=xxxxx-xxx-cdh-cdn005.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.0m (61943905274)
Instance 94481a81355e51e4:51fd9f9500000046 (host=xxxxx-xxx-cdh-cdn027.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.0m (61955797776)
Instance 94481a81355e51e4:51fd9f950000004e (host=xxxxx-xxx-cdh-cdn021.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 1.0m (60045780252)
Instance 94481a81355e51e4:51fd9f9500000040 (host=xxxxx-xxx-cdh-cdn029.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 58.05s (58048904552)
Instance 94481a81355e51e4:51fd9f950000004a (host=xxxxx-xxx-cdh-cdn023.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 57.34s (57338024825)
Instance 94481a81355e51e4:51fd9f9500000049 (host=xxxxx-xxx-cdh-cdn008.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 53.13s (53130104765)
Instance 94481a81355e51e4:51fd9f9500000056 (host=xxxxx-xxx-cdh-cdn004.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 43.24s (43238668974)
Instance 94481a81355e51e4:51fd9f950000003e (host=xxxxx-xxx-cdh-cdn015.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=0)
- TotalTime: 56.2m (3373973559713)
我省略了其他不相关的信息，只留下了我感兴趣的信息。现在我可以清楚地看到哪个服务器节点是瓶颈，它是主机xxxxx-xxx-cdh-cdn015.xxx.XXXXXX.com，用时56.2分钟，而其他所有主机用时约40秒至2分钟。
现在，我记得另一个HDFS SCAN具有相同的问题，即操作01（01：SCAN HDFS），所以我执行了相同的egrep命令（请记住，不同操作的缩进可能不同，所以我需要在Profile文件中搜索到那个操作，然后将其之前的空格完全复制粘贴，以获得我想要的结果）：
代码语言：javascript复制egrep ' Instance .*)|^ HDFS_SCAN_NODE (id=1)|^ - TotalTime: ' profile-example.txt
结果再次证实了同样的结论：
代码语言：javascript复制....
Instance 94481a81355e51e4:51fd9f950000000c (host=xxxxx-xxx-cdh-cdn015.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=1)
- TotalTime: 13.3m (798747290751)
...
Instance 94481a81355e51e4:51fd9f9500000007 (host=xxxxx-xxx-cdh-cdn001.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=1)
- TotalTime: 28.16s (28163113611)
Instance 94481a81355e51e4:51fd9f9500000018 (host=xxxxx-xxx-cdh-cdn009.xxx.XXXXXX.com:22000)
...
HDFS_SCAN_NODE (id=1)
- TotalTime: 23.29s (23285966387)
...
很明显，同样的主机xxxxx-xxx-cdh-cdn015.xxx.XXXXXX.com也有同样的问题，它的运行速度比其他主机慢得多，13.3分钟比 28.16秒。
然后我得出结论，该服务器出现了一些问题，需要修复。
为了确认我经过排查得出的结论，我要求用户停掉这个主机上的Impalad进程并再次测试他们的查询，他们确认问题已经解决，后来他们反馈说他们发现那台服务器硬件有问题，已经对其停机维护了。
原文参考：
代码语言：javascript复制https://www.ericlin.me/2020/01/impala-query-profile-explained-part-4/
https://my.oschina.net/dabird/blog/3163584
