大多数情况下,此查询在10秒内返回,但偶尔需要40秒或更长时间。
群集中有两个执行器节点,两个节点的配置文件没有显著差异,以下是其中之一:
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秒花在哪里。
你能提出可能的问题吗?我该怎么解决?
2条答案
按热度按时间ztyzrc3y1#
扫描节点中的线程模型非常复杂,因为有两层工作线程用于扫描和I/O -我将称之为扫描器和I/O线程。我将自上而下地指出一些潜在的瓶颈以及如何识别它们。
RowBatchQueueGetWaitTime高表示扫描所消耗的主线程花费大量时间等待扫描程序线程生成行。差异的一个主要来源可能是扫描程序线程数-如果系统处于资源压力下,则每个查询获得的线程数可能会减少。因此,请密切关注AverageScannerThreadConcurrency以了解该值是否存在变化。
扫描器线程将花费时间做各种事情。
1.未运行,因为操作系统调度了另一个线程。
1.正在等待I/O线程从存储系统读取数据
1.解码数据、评估 predicate 、其他工作
对于#1,您会看到ScannerThreadsInvoluntaryContextSwitches和ScannerThreadsUserTime/ScannerThreadsSysTime的值较高,远低于ScannerThreadsTotalWallClockTime。如果ScannerThreadsUserTime远低于MaterializeTupleTime,则这是另一种症状。
对于#2,您会看到很高的ScannerThreadsUserTime和MaterializeTupleTime。看起来这里有大量的CPU时间用于此,但不是大部分时间。
要确定第三个问题,我建议查看片段配置文件中的TotalStorageWaitTime,以了解线程实际花费了多少时间等待I/O。我还在最近的Impala版本中添加了ScannerIoWaitTime,因为它位于扫描程序配置文件中,所以更加方便。
如果存储等待时间较长,则需要考虑以下几点
我怀疑在您的情况下,根本原因是打开此查询的文件速度慢,以及打开其他查询的文件速度慢,导致扫描器线程被占用。启用文件句柄缓存可能会解决问题-我们已经看到通过这样做,生产部署的性能有了显著提高。
另一个值得一提的可能性是,内置JVM正在进行一些垃圾收集-这可能会阻塞一些HDFS操作。我们有一些暂停检测,当JVM暂停时会记录消息。您也可以查看/memz调试页面,我认为其中有一些GC统计信息。或者连接其他Java调试工具。
qnyhuwrf2#
ScannerThreadsVoluntaryContextSwitches: 1.25K (1248)
表示有1248种情况是扫描线程“卡住”等待某个外部资源,随后进入休眠状态()。该资源很可能是磁盘IO。这可以解释为什么平均阅读速度(TotalReadThroughput: *11.70 MB*/sec
)非常低,而每次读取吞吐量(PerReadThreadRawHdfsThroughput: 151.39 MB/sec
)却“正常”。要提高性能,您可能需要尝试:
dfs.client.read.shortcircuit=true
)(Note这两种方法都适用于在HDFS上运行Impala,而不是在某种对象存储上运行。)