olap - 为什么 Impala 扫描节点非常慢 (RowBatchQueueGetWaitTime)？

Question

大多数情况下，此查询会在 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 秒花在哪里。
你能提出可能的问题吗，我该如何解决？

Answer 1

扫描节点中的线程模型非常复杂，因为有两层工作线程用于扫描和 I/O - 我将它们称为扫描器和 I/O 线程。我将自上而下指出一些潜在的瓶颈以及如何识别它们。
高 RowBatchQueueGetWaitTime 表示从扫描中消耗的主线程花费大量时间等待扫描器线程生成行。一个主要的差异来源可能是扫描器线程的数量——如果系统处于资源压力之下，每个查询可以获得更少的线程。因此，请密切关注 AverageScannerThreadConcurrency 以了解它是否有所变化。
扫描仪线程将花时间做各种事情。大部分时间一般是

未运行，因为操作系统调度了不同的线程。

等待 I/O 线程从存储系统读取数据

解码数据，评估谓词，其他工作

使用 #1，您会看到 ScannerThreadsInventorContextSwitches 和 ScannerThreadsUserTime/ScannerThreadsSysTime 的值比 ScannerThreadsT​​otalWallClockTime 低得多。如果 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 很高，则从存储系统读取可能会很慢(例如，如果数据不在操作系统缓冲区缓存中或者它是像 S3 这样的远程文件系统)

其他查询可能正在争夺 I/O 资源和/或 I/O 线程

我怀疑在您的情况下，根本原因是打开此查询的文件缓慢，以及打开其他查询的文件缓慢导致扫描器线程被占用。启用文件句柄缓存可能会解决这个问题——通过这样做，我们已经看到生产部署的性能有了显着的提高。
另一个值得一提的可能性是内置 JVM 正在执行一些垃圾收集 - 这可能会阻止某些 HDFS 操作。我们有一些暂停检测，可以在 JVM 暂停时记录消息。您还可以查看/memz 调试页面，我认为其中有一些 GC 统计信息。或者连接其他Java调试工具。