一步一步理解Impala query profile（四）

九州暮云

发布于 2020-02-18 13:31:23

7240

发布于 2020-02-18 13:31:23

在本系列的第三部分，我使用了一个示例来详细地介绍Impala query profile。在这一部分中，我将使用一个真实生产系统的Impala Profile文件，解释我在遇到问题时阅读Profile文件的步骤，并逐渐找到引起问题的真正原因。如果你错过了我的文章的前3个部分，你可以点击以下链接阅读一下：

一步一步理解Impala query profile（一）
一步一步理解Impala query profile（二）
一步一步理解Impala query profile（三）

好了，我们开始吧。由于Profile文件本身相当大，因为它涉及到多个Impalad进程，所以如果我将完整的内容在页面上显示出来，页面就会很难看。因此，请从这个链接下载，并在你本地电脑或浏览器上来查看这个文件。

这个查询的问题是，不知道出于什么原因，之前执行相同的查询几分钟内就可以完成，但现在要花1个多小时才能完成。这个Profile文件只是其中的一个例子，实际上，当时在这个集群中运行的所有查询都有相同的问题。所以请花点时间看一下这个Profile，看看你是否能获取什么有用的信息，并对问题产生的场景有一个大致的了解。

现在，让我们一起来看看排查该问题的步骤。

1、由于用户反馈查询时间比正常情况下长，我想知道的第一件事是到底花费了多长时间？所以首先，我在Profile的开头查看查询开始和结束的时间：

Start Time: 2020-01-03 07:33:42.928171000
End Time: 2020-01-03 08:47:55.745537000

我发现，现在完成查询需要1小时14分钟，这与用户的反馈是相符的。

2、由于用户取消，查询异常失败：

Query State: EXCEPTION
Query Status: Cancelled

用户已经没有耐心了，不得不取消查询，因为它运行了太长时间，这里没什么好担心的。

3、接下来，我检查了查询的复杂程度：

    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）节点的主机名称：

Coordinator: xxxxx-xxx-cdh-cdn003.xxx.XXXXXX.com:22000

如果我不能从这个Profile文件得出任何结论，那么下一步应该是获取这个主机上的impalad日志。但是现在，我只能继续，因为我还没有日志。

5、正如我在上一篇文章中提到的，Profile文件接下来的部分是查询计划（Query Plan），通常我会先跳过这部分，然后跳到概要（Summary）部分，以了解每个操作花了多长时间，并查看是否有什么明显的信息可能会让我有所发现：

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”的第一部分：

    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。为了确认，我向后滚动并看到以下内容：

Averaged Fragment F00

继续搜索文件，我来到下面部分(第二个实例“id=0”)：

            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分钟要快，然后我回滚到前面以确认主机：

    Fragment F00
      Instance 94481a81355e51e4:51fd9f9500000053 (host=xxxxx-xxx-cdh-cdn002.xxx.XXXXXX.com:22000)

现在，可以看到我找到的三个主要信息：

      Instance 94481a81355e51e4:51fd9f9500000053 (host=xxxxx-xxx-cdh-cdn002.xxx.XXXXXX.com:22000)
            HDFS_SCAN_NODE (id=0)
              - TotalTime: 2.1m (125005670562)

接下来我使用grep过滤出我想要的内容。由于Profile文件已缩进，因此我使用egrep执行了下面的操作：

egrep ' Instance .*\)|^            HDFS_SCAN_NODE \(id=0\)|^              - TotalTime: ' profile-example.txt

结果如下：

...
      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文件中搜索到那个操作，然后将其之前的空格完全复制粘贴，以获得我想要的结果）：

egrep ' Instance .*\)|^            HDFS_SCAN_NODE \(id=1\)|^              - TotalTime: ' profile-example.txt

结果再次证实了同样的结论：

....
      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进程并再次测试他们的查询，他们确认问题已经解决，后来他们反馈说他们发现那台服务器硬件有问题，已经对其停机维护了。

编译自：IMPALA QUERY PROFILE EXPLAINED – PART 4

本文参与腾讯云自媒体分享计划，分享自作者个人站点/博客。

如有侵权请联系 cloudcommunity@tencent.com 删除

大数据