本文档主要介绍 Doris 在查询执行的统计结果。利用这些统计的信息,可以更好的帮助我们了解 Doris 的执行情况,并有针对性的进行相应 Debug 与调优工作。
名词解释
FE:Frontend,Doris 的前端节点。负责元数据管理和请求接入。
BE:Backend,Doris 的后端节点。负责查询执行和数据存储。
Fragment:FE 会将具体的 SQL 语句的执行转化为对应的 Fragment 并下发到 BE 进行执行。BE 上执行对应 Fragment,并将结果汇聚返回给 FE。
基本原理
FE 将查询计划拆分成为 Fragment 下发到 BE 进行任务执行。BE 在执行 Fragment 时记录了运行状态时的统计值,并将 Fragment 执行的统计信息输出到日志之中。 FE 也可以通过开关将各个 Fragment 记录的这些统计值进行搜集,并在 FE 的 Web 页面上打印结果。
操作流程
通过 Mysql 命令,将 FE 上的 Report 的开关打开。
mysql> set enable_profile=true;
之后执行对应的 SQL 语句之后(旧版本为is_report_success
),在 FE 的 Web 页面就可以看到对应 SQL 语句执行的 Report 信息:
这里会列出最新执行完成的100条语句,我们可以通过 Profile 查看详细的统计信息。
Query:
Summary:
Query ID: 9664061c57e84404-85ae111b8ba7e83a
Start Time: 2020-05-02 10:34:57
End Time: 2020-05-02 10:35:08
Total: 10s323ms
Query Type: Query
Query State: EOF
Doris Version: trunk
User: root
Default Db: default_cluster:test
Sql Statement: select max(Bid_Price) from quotes group by Symbol
这里详尽的列出了查询的 ID,执行时间,执行语句等等的总结信息。接下来内容是打印从 BE 收集到的各个 Fragment 的详细信息。
Fragment 0:
Instance 9664061c57e84404-85ae111b8ba7e83d (host=TNetworkAddress(hostname:192.168.0.1, port:9060)):(Active: 10s270ms, % non-child: 0.14%)
- MemoryLimit: 2.00 GB
- BytesReceived: 168.08 KB
- PeakUsedReservation: 0.00
- SendersBlockedTimer: 0ns
- DeserializeRowBatchTimer: 501.975us
- PeakMemoryUsage: 577.04 KB
- RowsProduced: 8.322K (8322)
EXCHANGE_NODE (id=4):(Active: 10s256ms, % non-child: 99.35%)
- ConvertRowBatchTime: 180.171us
- PeakMemoryUsage: 0.00
- RowsReturned: 8.322K (8322)
- MemoryUsed: 0.00
- RowsReturnedRate: 811
这里列出了 Fragment 的 ID。
hostname
指的是执行 Fragment 的 BE 节点。
Active:10s270ms
表示该节点的执行总时间。
non-child: 0.14%
表示执行节点自身的执行时间(不包含子节点的执行时间)占总时间的百分比。
PeakMemoryUsage
表示EXCHANGE_NODE
内存使用的峰值。
RowsReturned
表示EXCHANGE_NODE
结果返回的行数。
RowsReturnedRate
=RowsReturned
/ActiveTime
。
这三个统计信息在其他NODE
中的含义相同。
后续依次打印子节点的统计信息,这里可以通过缩进区分节点之间的父子关系。
Profile参数解析
BE 端收集的统计信息较多,下面列出了各个参数的对应含义:
Fragment
AverageThreadTokens: 执行 Fragment 使用线程数目,不包含线程池的使用情况。
Buffer Pool PeakReservation: Buffer Pool 使用的内存的峰值。
MemoryLimit: 查询时的内存限制。
PeakMemoryUsage: 整个 Instance 在查询时内存使用的峰值。
RowsProduced: 处理列的行数。
BlockMgr
BlocksCreated: BlockMgr 创建的 Blocks 数目。
BlocksRecycled: 重用的 Blocks 数目。
BytesWritten: 总的落盘写数据量。
MaxBlockSize: 单个 Block 的大小。
TotalReadBlockTime: 读 Block 的总耗时。
DataStreamSender
BytesSent: 发送的总数据量 = 接受者 * 发送数据量。
IgnoreRows: 过滤的行数。
LocalBytesSent: 数据在 Exchange 过程中,记录本机节点的自发自收数据量。
OverallThroughput: 总的吞吐量 = BytesSent/时间。
SerializeBatchTime: 发送数据序列化消耗的时间。
UncompressedRowBatchSize: 发送数据压缩前的 RowBatch 的大小。
ODBC_TABLE_SINK
NumSentRows: 写入外表的总行数。
TupleConvertTime: 发送数据序列化为 Insert 语句的耗时。
ResultSendTime: 通过 ODBC Driver 写入的耗时。
EXCHANGE_NODE
BytesReceived: 通过网络接收的数据量大小。
MergeGetNext: 当下层节点存在排序时,会在 EXCHANGE NODE 进行统一的归并排序,输出有序结果。该指标记录了 Merge 排序的总耗时,包含了 MergeGetNextBatch 耗时。
MergeGetNextBatch:Merge 节点取数据的耗时,如果为单层 Merge 排序,则取数据的对象为网络队列。若为多层 Merge 排序取数据对象为 Child Merger。
ChildMergeGetNext: 当下层的发送数据的 Sender 过多时,单线程的 Merge 会成为性能瓶颈,Doris 会启动多个 Child Merge 线程并行归并排序。记录了 Child Merge 的排序耗时 该数值是多个线程的累加值。
ChildMergeGetNextBatch: Child Merge 节点从取数据的耗时,如果耗时过大,可能的瓶颈为下层的数据发送节点。
DataArrivalWaitTime: 等待 Sender 发送数据的总时间。
FirstBatchArrivalWaitTime: 等待第一个 batch 从 Sender 获取的时间。
DeserializeRowBatchTimer: 反序列化网络数据的耗时。
SendersBlockedTotalTimer(*): DataStreamRecv 的队列的内存被打满,Sender 端等待的耗时。
ConvertRowBatchTime: 接收数据转为 RowBatch 的耗时。
RowsReturned: 接收行的数目。
RowsReturnedRate: 接收行的速率。
SORT_NODE
InMemorySortTime: 内存之中的排序耗时。
InitialRunsCreated: 初始化排序的趟数(如果内存排序的话,该数为1)。
SortDataSize: 总的排序数据量。
MergeGetNext: MergeSort 从多个 sort_run 获取下一个 batch 的耗时 (仅在落盘时计时)。
MergeGetNextBatch: MergeSort 提取下一个 sort_run的batch 的耗时 (仅在落盘时计时)。
TotalMergesPerformed: 进行外排 merge 的次数。
AGGREGATION_NODE
PartitionsCreated: 聚合查询拆分成 Partition 的个数。
GetResultsTime: 从各个 partition 之中获取聚合结果的时间。
HTResizeTime: HashTable 进行 resize 消耗的时间。
HTResize: HashTable 进行 resize 的次数。
HashBuckets: HashTable 中 Buckets 的个数。
HashBucketsWithDuplicate: HashTable 有 DuplicateNode 的 Buckets 的个数。
HashCollisions: HashTable 产生哈希冲突的次数。
HashDuplicateNodes: HashTable 出现 Buckets 相同 DuplicateNode 的个数。
HashFailedProbe: HashTable Probe 操作失败的次数。
HashFilledBuckets: HashTable 填入数据的 Buckets 数目。
HashProbe: HashTable 查询的次数。
HashTravelLength: HashTable 查询时移动的步数。
HASH_JOIN_NODE
ExecOption: 对右孩子构造HashTable的方式(同步or异步),Join中右孩子可能是表或子查询,左孩子同理。
BuildBuckets: HashTable 中 Buckets 的个数。
BuildRows: HashTable 的行数。
BuildTime: 构造 HashTable 的耗时。
LoadFactor: HashTable 的负载因子(即非空 Buckets 的数量)。
ProbeRows: 遍历左孩子进行 Hash Probe 的行数。
ProbeTime: 遍历左孩子进行 Hash Probe 的耗时,不包括对左孩子 RowBatch 调用 GetNext 的耗时
PushDownComputeTime: 谓词下推条件计算耗时。
PushDownTime: 谓词下推的总耗时,Join 时对满足要求的右孩子,转为左孩子的 in 查询。
CROSS_JOIN_NODE
ExecOption: 对右孩子构造 RowBatchList 的方式(同步 or 异步)。
BuildRows: RowBatchList 的行数(即右孩子的行数)。
BuildTime: 构造 RowBatchList 的耗时。
LeftChildRows: 左孩子的行数。
LeftChildTime: 遍历左孩子,和右孩子求笛卡尔积的耗时,不包括对左孩子 RowBatch 调用 GetNext 的耗时。
UNION_NODE
MaterializeExprsEvaluateTime: Union 两端字段类型不一致时,类型转换表达式计算及物化结果的耗时。
ANALYTIC_EVAL_NODE
EvaluationTime: 分析函数(窗口函数)计算总耗时。
GetNewBlockTime: 初始化时申请一个新的 Block 的耗时,Block 用来缓存 Rows 窗口或整个分区,用于分析函数计算。
PinTime: 后续申请新的 Block 或将写入磁盘的 Block 重新读取回内存的耗时。
UnpinTime: 对暂不需要使用的 Block 或当前操作符内存压力大时,将 Block 的数据刷入磁盘的耗时。
OLAP_SCAN_NODE
OLAP_SCAN_NODE
节点负责具体的数据扫描任务。一个 OLAP_SCAN_NODE
会生成一个或多个 OlapScanner
。每个 Scanner 线程负责扫描部分数据。
查询中的部分或全部谓词条件会推送给 OLAP_SCAN_NODE
。这些谓词条件中一部分会继续下推给存储引擎,以便利用存储引擎的索引进行数据过滤。另一部分会保留在 OLAP_SCAN_NODE
中,用于过滤从存储引擎中返回的数据。
OLAP_SCAN_NODE
节点的 Profile 通常用于分析数据扫描的效率,依据调用关系分为 OLAP_SCAN_NODE
、OlapScanner
、SegmentIterator
三层。
一个典型的 OLAP_SCAN_NODE
节点的 Profile 如下。部分指标会因存储格式的不同(V1 或 V2)而有不同含义。
OLAP_SCAN_NODE (id=0):(Active: 1.2ms, % non-child: 0.00%)
- BytesRead: 265.00 B
- NumDiskAccess: 1
- NumScanners: 20
- PeakMemoryUsage: 0.00
- RowsRead: 7
- RowsReturned: 7
- RowsReturnedRate: 6.979K /sec
- TabletCount : 20
- TotalReadThroughput: 74.70 KB/sec
- ScannerBatchWaitTime: 426.886us
- ScannerWorkerWaitTime: 17.745us
OlapScanner:
- BlockConvertTime: 8.941us
- BlockFetchTime: 468.974us
- ReaderInitTime: 5.475ms
- RowsDelFiltered: 0
- RowsPushedCondFiltered: 0
- ScanTime: 39.24us
- ShowHintsTime_V1: 0ns
SegmentIterator:
- BitmapIndexFilterTimer: 779ns
- BlockLoadTime: 415.925us
- BlockSeekCount: 12
- BlockSeekTime: 222.556us
- BlocksLoad: 6
- CachedPagesNum: 30
- CompressedBytesRead: 0.00
- DecompressorTimer: 0ns
- IOTimer: 0ns
- IndexLoadTime_V1: 0ns
- NumSegmentFiltered: 0
- NumSegmentTotal: 6
- RawRowsRead: 7
- RowsBitmapIndexFiltered: 0
- RowsBloomFilterFiltered: 0
- RowsKeyRangeFiltered: 0
- RowsStatsFiltered: 0
- RowsConditionsFiltered: 0
- RowsVectorPredFiltered: 0
- TotalPagesNum: 30
- UncompressedBytesRead: 0.00
- VectorPredEvalTime: 0ns
通过 Profile 中数据行数相关指标可以推断谓词条件下推和索引使用情况。以下仅针对 Segment V2 格式数据读取流程中的 Profile 进行说明。Segment V1 格式中,这些指标的含义略有不同。
当读取一个 V2 格式的 Segment 时,若查询存在 key_ranges(前缀 key 组成的查询范围),首先通过 SortkeyIndex 索引过滤数据,过滤的行数记录在 RowsKeyRangeFiltered
。
之后,对查询条件中含有 bitmap 索引的列,使用 Bitmap 索引进行精确过滤,过滤的行数记录在 RowsBitmapIndexFiltered
。
之后,按查询条件中的等值(eq,in,is)条件,使用 BloomFilter 索引过滤数据,记录在 RowsBloomFilterFiltered
。RowsBloomFilterFiltered
的值是 Segment 的总行数(而不是Bitmap索引过滤后的行数)和经过 BloomFilter 过滤后剩余行数的差值,因此 BloomFilter 过滤的数据可能会和 Bitmap 过滤的数据有重叠。
之后,按查询条件和删除条件,使用 ZoneMap 索引过滤数据,记录在 RowsStatsFiltered
。
RowsConditionsFiltered
是各种索引过滤的行数,包含了 RowsBloomFilterFiltered
和 RowsStatsFiltered
的值。
至此 Init 阶段完成,Next 阶段删除条件过滤的行数,记录在 RowsDelFiltered
。因此删除条件实际过滤的行数,分别记录在 RowsStatsFiltered
和 RowsDelFiltered
中。
RawRowsRead
是经过上述过滤后,最终需要读取的行数。
RowsRead
是最终返回给 Scanner 的行数。RowsRead
通常小于 RawRowsRead
,是因为从存储引擎返回到 Scanner,可能会经过一次数据聚合。如果 RawRowsRead
和 RowsRead
差距较大,则说明大量的行被聚合,而聚合可能比较耗时。
RowsReturned
是 ScanNode 最终返回给上层节点的行数。RowsReturned
通常也会小于RowsRead
。因为在 Scanner 上会有一些没有下推给存储引擎的谓词条件,会进行一次过滤。如果 RowsRead
和 RowsReturned
差距较大,则说明很多行在 Scanner 中进行了过滤。这说明很多选择度高的谓词条件并没有推送给存储引擎。而在 Scanner 中的过滤效率会比在存储引擎中过滤效率差。
通过以上指标,可以大致分析出存储引擎处理的行数以及最终过滤后的结果行数大小。通过 Rows***Filtered
这组指标,也可以分析查询条件是否下推到了存储引擎,以及不同索引的过滤效果。此外还可以通过以下几个方面进行简单的分析。
OlapScanner
下的很多指标,如 IOTimer
,BlockFetchTime
等都是所有 Scanner 线程指标的累加,因此数值可能会比较大。并且因为 Scanner 线程是异步读取数据的,所以这些累加指标只能反映 Scanner 累加的工作时间,并不直接代表 ScanNode 的耗时。ScanNode 在整个查询计划中的耗时占比为 Active
字段记录的值。有时会出现例如 IOTimer
有几十秒,而 Active
实际只有几秒钟。这种情况通常因为:
IOTimer
为多个 Scanner 的累加时间,而 Scanner 数量较多。
上层节点比较耗时。例如上层节点耗时 100秒,而底层 ScanNode 只需 10秒。则反映在 Active
的字段可能只有几毫秒。因为在上层处理数据的同时,ScanNode 已经异步的进行了数据扫描并准备好了数据。当上层节点从 ScanNode 获取数据时,可以获取到已经准备好的数据,因此 Active 时间很短。
NumScanners
表示 Scanner 提交到线程池的Task个数,由 RuntimeState
中的线程池调度,doris_scanner_thread_pool_thread_num
和 doris_scanner_thread_pool_queue_size
两个参数分别控制线程池的大小和队列长度。线程数过多或过少都会影响查询效率。同时可以用一些汇总指标除以线程数来大致的估算每个线程的耗时。
TabletCount
表示需要扫描的 tablet 数量。数量过多可能意味着需要大量的随机读取和数据合并操作。
UncompressedBytesRead
间接反映了读取的数据量。如果该数值较大,说明可能有大量的 IO 操作。
CachedPagesNum
和 TotalPagesNum
可以查看命中 PageCache 的情况。命中率越高,说明 IO 和解压操作耗时越少。
Buffer pool
AllocTime: 内存分配耗时。
CumulativeAllocationBytes: 累计内存分配的量。
CumulativeAllocations: 累计的内存分配次数。
PeakReservation: Reservation 的峰值。
PeakUnpinnedBytes: unpin 的内存数据量。
PeakUsedReservation: Reservation 的内存使用量。
ReservationLimit: BufferPool的Reservation 的限制量。
本页内容是否解决了您的问题?