为什么 Impala 扫描节点非常慢（RowBatchQueueGetWaitTime）？

Question

该查询大多数情况下会在 10 秒内返回，但有时需要 40 秒或更长时间。

swarm中有两个执行器节点，两个节点的配置文件没有显着差异，以下是其中之一：

      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 秒花在哪里。

您能否建议可能出现的问题以及如何解决？

Answer 1

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

高 RowBatchQueueGetWaitTime 表示扫描消耗的主线程花费了大量时间等待扫描器线程生成行。差异的一个主要来源可能是扫描器线程的数量 - 如果系统面临资源压力，则每个查询可以获得更少的线程。因此，请密切关注 AverageScannerThreadConcurrency 以了解其是否有所变化。

扫描仪线程将花费时间做各种事情。大部分时间一般是

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

使用#1，您会看到 ScannerThreadsInvolentContextSwitches 和 ScannerThreadsUserTime/ScannerThreadsSysTime 的值较高，远低于 ScannerThreadsT​​otalWallClockTime。如果 ScannerThreadsUserTime 远低于 MaterializeTupleTime，那将是另一个症状。

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

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

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

• 如果 TotalRawHdfsOpenFileTime 较高，则打开文件可能是瓶颈。这可能发生在任何存储系统上，包括 HDFS。请参阅为什么 Impala 花费大量时间打开 HDFS 文件 (TotalRawHdfsOpenFileTime)？
• 如果 TotalRawHdfsReadTime 较高，则从存储系统读取可能会很慢（例如，如果数据不在操作系统缓冲区缓存中或者是 S3 等远程文件系统）
• 其他查询可能会争夺 I/O 资源和/或 I/O 线程

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

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