为什么 Impala 扫描节点很慢（RowBatchQueueGetWaitTime）？答案

【问题标题】：Why Impala Scan Node is very slow (RowBatchQueueGetWaitTime)?为什么 Impala 扫描节点很慢（RowBatchQueueGetWaitTime）？
【发布时间】：2020-08-14 02:34:43
【问题描述】：

此查询大部分时间在 10 秒内返回，但偶尔需要 40 秒或更长时间。

swarm 中有两个执行者节点，两个节点的 profile 没有显着差异，以下是其中之一：

      HDFS_SCAN_NODE (id=0):(Total: 39s818ms, non-child: 39s818ms, % non-child: 100.00%)
     - AverageHdfsReadThreadConcurrency: 0.07 
     - AverageScannerThreadConcurrency: 1.47 
     - BytesRead: 563.73 MB (591111366)
     - BytesReadDataNodeCache: 0
     - BytesReadLocal: 0
     - BytesReadRemoteUnexpected: 0
     - BytesReadShortCircuit: 0
     - CachedFileHandlesHitCount: 0 (0)
     - CachedFileHandlesMissCount: 560 (560)
     - CollectionItemsRead: 0 (0)
     - DecompressionTime: 1s501ms
     - MaterializeTupleTime(*): 11s685ms
     - MaxCompressedTextFileLength: 0
     - NumColumns: 9 (9)
     - NumDictFilteredRowGroups: 0 (0)
     - NumDisksAccessed: 1 (1)
     - NumRowGroups: 56 (56)
     - NumScannerThreadMemUnavailable: 0 (0)
     - NumScannerThreadReservationsDenied: 0 (0)
     - NumScannerThreadsStarted: 4 (4)
     - NumScannersWithNoReads: 0 (0)
     - NumStatsFilteredRowGroups: 0 (0)
     - PeakMemoryUsage: 142.10 MB (149004861)
     - PeakScannerThreadConcurrency: 2 (2)
     - PerReadThreadRawHdfsThroughput: 151.39 MB/sec
     - RemoteScanRanges: 1.68K (1680)
     - RowBatchBytesEnqueued: 2.32 GB (2491334455)
     - RowBatchQueueGetWaitTime: 39s786ms
     - RowBatchQueuePeakMemoryUsage: 1.87 MB (1959936)
     - RowBatchQueuePutWaitTime: 0.000ns
     - RowBatchesEnqueued: 6.38K (6377)
     - RowsRead: 73.99M (73994828)
     - RowsReturned: 6.40M (6401849)
     - RowsReturnedRate: 161.27 K/sec
     - ScanRangesComplete: 56 (56)
     - ScannerThreadsInvoluntaryContextSwitches: 99 (99)
     - ScannerThreadsTotalWallClockTime: 1m10s
       - ScannerThreadsSysTime: 630.808ms
       - ScannerThreadsUserTime: 12s824ms
     - ScannerThreadsVoluntaryContextSwitches: 1.25K (1248)
     - TotalRawHdfsOpenFileTime(*): 9s396ms
     - TotalRawHdfsReadTime(*): 3s789ms
     - TotalReadThroughput: 11.70 MB/sec
    Buffer pool:
       - AllocTime: 1.240ms
       - CumulativeAllocationBytes: 706.32 MB (740630528)
       - CumulativeAllocations: 578 (578)
       - PeakReservation: 140.00 MB (146800640)
       - PeakUnpinnedBytes: 0
       - PeakUsedReservation: 33.83 MB (35471360)
       - ReadIoBytes: 0
       - ReadIoOps: 0 (0)
       - ReadIoWaitTime: 0.000ns
       - WriteIoBytes: 0
       - WriteIoOps: 0 (0)
       - WriteIoWaitTime: 0.000ns

我们可以注意到 RowBatchQueueGetWaitTime 非常高，差不多 40 秒，但我不知道为什么，承认 TotalRawHdfsOpenFileTime 需要 9 秒，TotalRawHdfsReadTime 需要将近 4 秒，我仍然无法解释其他 27秒花费。

您能否提出可能的问题以及如何解决？

【问题讨论】：

标签： hadoop hdfs impala olap

【解决方案1】：

扫描节点中的线程模型非常复杂，因为有两层工作线程用于扫描和 I/O - 我将它们称为扫描器和 I/O 线程。我将自上而下指出一些潜在的瓶颈以及如何识别它们。

High RowBatchQueueGetWaitTime 表示从扫描中消耗的主线程正在花费大量时间等待扫描线程生成行。一个主要的差异来源可能是扫描器线程的数量——如果系统处于资源压力之下，每个查询可以获得更少的线程。因此，请密切关注 AverageScannerThreadConcurrency 以了解它是否有所不同。

扫描器线程会花时间做各种各样的事情。大部分时间一般是

未运行，因为操作系统安排了不同的线程。
等待 I/O 线程从存储系统读取数据
解码数据、评估谓词、其他工作

使用 #1，您会看到 ScannerThreadsInvoluntentContextSwitches 和 ScannerThreadsUserTime/ScannerThreadsSysTime 的值比 ScannerThreadsTotalWallClockTime 低得多。如果 ScannerThreadsUserTime 远低于 MaterializeTupleTime，那将是另一种症状。

使用#2，您会看到较高的 ScannerThreadsUserTime 和 MaterializeTupleTime。看起来这里有大量的 CPU 时间，但不是大部分时间。

要确定 #3，我建议查看片段配置文件中的 TotalStorageWaitTime，以了解线程实际花费了多少时间等待 I/O。我还在最近的 Impala 版本中添加了 ScannerIoWaitTime，这更方便，因为它位于扫描仪配置文件中。

如果存储等待时间很慢，有几点需要考虑

如果 TotalRawHdfsOpenFileTime 很高，则可能是打开文件是一个瓶颈。这可能发生在任何存储系统上，包括 HDFS。见Why Impala spend a lot of time Opening HDFS File (TotalRawHdfsOpenFileTime)?
如果 TotalRawHdfsReadTime 很高，从存储系统读取可能会很慢（例如，如果数据不在 OS 缓冲区缓存中，或者它是像 S3 这样的远程文件系统）
其他查询可能会争用 I/O 资源和/或 I/O 线程

我怀疑在您的情况下，根本原因是此查询打开文件缓慢，以及其他查询打开文件缓慢导致扫描仪线程被占用。启用文件句柄缓存可能会解决这个问题 - 我们已经看到通过这样做可以显着提高生产部署的性能。

另一个值得一提的可能性是内置 JVM 正在执行一些垃圾收集 - 这可能会阻止一些 HDFS 操作。我们有一些暂停检测，可以在 JVM 暂停时记录消息。您还可以查看 /memz 调试页面，我认为该页面有一些 GC 统计信息。或者连接其他 Java 调试工具。

【讨论】：

谢谢，这个答案很有帮助。但是我仍然想知道，如果您认为不是因为 I/O 性能问题，那么您如何解释 ScannerThreadsVoluntaryContextSwitches 非常高？

【解决方案2】：

ScannerThreadsVoluntaryContextSwitches: 1.25K (1248) 表示有 1248 种情况是扫描线程“卡住”等待某些外部资源，然后进入 sleep()。该资源很可能是磁盘 IO。这可以解释相当低的平均阅读速度（TotalReadThroughput: *11.70 MB*/sec），同时具有“正常”的每次阅读吞吐量（PerReadThreadRawHdfsThroughput: 151.39 MB/sec）。

编辑

要提高性能，您可能需要尝试：

启用short circuit reads (dfs.client.read.shortcircuit=true)
配置HDFS缓存和alter Impala table to use cache

（请注意，如果您针对 HDFS 运行 Impala，则两者都适用，而不是某种对象存储。）

【讨论】：

谢谢，这很有帮助！但我仍然想知道如何在不添加更多物理资源的情况下解决此问题，因为这些慢速扫描大多发生在特定表上，我想知道复制此表（以便分散有关此表的查询）是否有帮助
如果 HDFS 缓存有帮助，我会感到惊讶，而且通常最好避免手动缓存管理。我只见过它在特定节点上出现热点时特别有用，它是一种增加小表或分区复制的方法。
我也认为 I/O 性能理论可能是错误的。过去，当瓶颈是 HDFS 名称节点 RPC 时，我们通过花费大量时间来追逐 I/O 性能，从而艰难地学到了这一点。那时我们将 TotalRawHdfsOpenFileTime 包含在 TotalRawHdfsReadTime 中，因此无法在配置文件中区分两者。
@tim-armstrong 非常有趣，感谢您的见解！谢谢！最好检查一下 NN RPC 调用队列和时间，看看你是否正确 :)