一步一步理解 Impala query profile(四)

翻译: 九州暮云

作者: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进程,所以如果我将完整的内容在页面上显示出来,页面就会很难看。因此,请从以下链接下载,并在你本地电脑或浏览器上来查看这个文件。

https://www.ericlin.me/wp-content/uploads/2020/01/profile-example.txt

这个查询的问题是,不知道出于什么原因,之前执行相同的查询几分钟内就可以完成,但现在要花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进程并再次测试他们的查询,他们确认问题已经解决,后来他们反馈说他们发现那台服务器硬件有问题,已经对其停机维护了。

原文参考:

https://www.ericlin.me/2020/01/impala-query-profile-explained-part-4/

https://my.oschina.net/dabird/blog/3163584

我来评几句
登录后评论

已发表评论数()

相关站点

+订阅
热门文章