GaussDB数据库SQL执行信息

在SQL调优过程中经常需要执行EXPLAIN ANALYZE或EXPLAIN PERFORMANCE查看SQL语句实际执行信息，通过对比实际执行与优化器的估算之间的差别来为优化提供依据。EXPLAIN PERFORMANCE相对于EXPLAIN ANALYZE增加了每个DN上的执行信息。

以如下SQL语句为例：

select count(1) from t1;

执行EXPLAIN PERFORMANCE输出为：

gaussdb=# explain performance select count(1) from t1;
 id |             operation              |    A-time     | A-rows | E-rows | E-distinct | Peak Memory  | E-memory | A-width | E-width | E-costs 
----+------------------------------------+---------------+--------+--------+------------+--------------+----------+---------+---------+---------
  1 | ->  Aggregate                      | 9.326         |      1 |      1 |            | 14KB         |          |         |       8 | 209.10
  2 |    ->  Streaming (type: GATHER)    | 9.281         |      2 |      2 |            | 80KB         |          |         |       8 | 209.10
  3 |       ->  Aggregate                | [5.981,6.491] |      2 |      2 |            | [13KB, 13KB] | 1MB      |         |       8 | 209.01
  4 |          ->  Seq Scan on public.t1 | [2.553,2.909] |  20000 |  20000 |            | [15KB, 15KB] | 1MB      |         |       0 | 184.00
(4 rows)
 
          Memory Information (identified by plan id)          
--------------------------------------------------------------
 Coordinator Query Peak Memory:
         Query Peak Memory: 0MB
 DataNode Query Peak Memory
         datanode1 Query Peak Memory: 2MB
         datanode2 Query Peak Memory: 0MB
   1 --Aggregate
         Peak Memory: 14KB, Estimate Memory: 64MB
   2 --Streaming (type: GATHER)
         Peak Memory: 80KB, Estimate Memory: 64MB
   3 --Aggregate
         datanode1 Peak Memory: 13KB, Estimate Memory: 1024KB
         datanode2 Peak Memory: 13KB, Estimate Memory: 1024KB
   4 --Seq Scan on public.t1
         datanode1 Peak Memory: 15KB, Estimate Memory: 1024KB
         datanode2 Peak Memory: 15KB, Estimate Memory: 1024KB
(15 rows)
 
 Targetlist Information (identified by plan id) 
------------------------------------------------
   1 --Aggregate
         Output: count((count(1)))
   2 --Streaming (type: GATHER)
         Output: (count(1))
         Node/s: All datanodes
   3 --Aggregate
         Output: count(1)
   4 --Seq Scan on public.t1
         Output: c1, c2, c3, c4, c5
         Distribute Key: c1
(10 rows)
 
                                         Datanode Information (identified by plan id)                                         
------------------------------------------------------------------------------------------------------------------------------
   1 --Aggregate
         (actual time=9.326..9.326 rows=1 loops=1)
         (Buffers: 0)
         (CPU: ex c/r=-17813058098842432, ex row=2, ex cyc=-35626116197684864, inc cyc=71252232399791904)
   2 --Streaming (type: GATHER)
         (actual time=8.628..9.281 rows=2 loops=1)
         (Buffers: 0)
         (CPU: ex c/r=53439174298738384, ex row=2, ex cyc=106878348597476768, inc cyc=106878348597476768)
   3 --Aggregate
         datanode1 (actual time=5.980..5.981 rows=1 loops=1)
         datanode2 (actual time=6.491..6.491 rows=1 loops=1)
         datanode1 (Buffers: shared hit=85)
         datanode2 (Buffers: shared hit=84)
         datanode1 (CPU: ex c/r=-35622581151734248, ex row=10078, ex cyc=-359004372847177760768, inc cyc=71252232395610160)
         datanode2 (CPU: ex c/r=-35622525572390744, ex row=9922, ex cyc=-353446698729260974080, inc cyc=71252232398542704)
   4 --Seq Scan on public.t1
         datanode1 (actual time=0.018..2.553 rows=10078 loops=1)
         datanode2 (actual time=0.017..2.909 rows=9922 loops=1)
         datanode1 (Buffers: shared hit=85)
         datanode2 (Buffers: shared hit=84)
         datanode1 (CPU: ex c/r=35629651228376004, ex row=10078, ex cyc=359075625079573381120, inc cyc=359075625079573381120)
         datanode2 (CPU: ex c/r=35629706809278324, ex row=9922, ex cyc=353517950961659543552, inc cyc=353517950961659543552)
(22 rows)
 
                           User Define Profiling                           
---------------------------------------------------------------------------
 Plan Node id: 2  Track name: coordinator get datanode connection
        coordinator1: (time=0.019 total_calls=1 loops=1)
 Plan Node id: 2  Track name: Coordinator serialize plan
        coordinator1: (time=1.059 total_calls=1 loops=1)
 Plan Node id: 2  Track name: Coordinator send begin command
        coordinator1: (time=0.003 total_calls=1 loops=1)
 Plan Node id: 2  Track name: Coordinator start transaction and send query
        coordinator1: (time=0.045 total_calls=1 loops=1)
(8 rows)
 
                        ====== Query Summary =====                        
--------------------------------------------------------------------------
 Datanode executor start time [datanode1, datanode2]: [0.421 ms,0.450 ms]
 Datanode executor run time [datanode1, datanode2]: [6.002 ms,6.528 ms]
 Datanode executor end time [datanode2, datanode1]: [0.027 ms,0.028 ms]
 Remote query poll time: 0.000 ms, Deserialze time: 0.000 ms
 System available mem: 8222310KB
 Query Max mem: 8310784KB
 Query estimated mem: 2048KB
 Coordinator executor start time: 0.181 ms
 Coordinator executor run time: 9.340 ms
 Coordinator executor end time: 0.052 ms
 Planner runtime: 0.421 ms
 Plan size: 3122 byte
 Query Id: 72339069014648468
 Total runtime: 9.657 ms
(14 rows)

图中显示执行信息分为以下7个部分

1. 以表格的形式将计划显示出来，包含有11个字段，分别是：id、operation、A-time、A-rows、E-rows、E-distinct、Peak Memory、E-memory、A-width、E-width和E-costs。其中计划类字段（id、operation以及E开头字段）的含义与执行EXPLAIN时的含义一致，详见执行计划小节中的说明。A-time、A-rows、E-distinct、Peak Memory、A-width的含义说明如下：
   • A-time：当前算子执行完成时间，一般DN上执行的算子的A-time是由[]括起来的两个值，分别表示此算子在所有DN上完成的最短时间和最长时间。
   • A-rows：表示当前算子的实际输出元组数。
   • E-distinct：表示hashjoin算子的distinct估计值。
   • Peak Memory：此算子在每个DN上执行时使用的内存峰值。
   • A-width：表示当前算子每行元组的实际宽度，仅对于重内存使用算子会显示，包括：(Vec)HashJoin、(Vec)HashAgg、(Vec) HashSetOp、(Vec)Sort、(Vec)Materialize算子等，其中(Vec)HashJoin计算的宽度是其右子树算子的宽度，会显示在其右子树上。
2. Predicate Information (identified by plan id)：

   这一部分主要显示的是静态信息，即在整个计划执行过程中不会变的信息，主要是一些join条件和一些filter信息。

3. Memory Information (identified by plan id)：

   这一部分显示的是整个计划中会将内存的使用情况打印出来的算子的内存使用信息，主要是Hash、Sort算子，包括算子峰值内存（peak memory），控制内存（control memory），估算内存使用（operator memory），执行时实际宽度（width），内存使用自动扩展次数（auto spread num），是否提前下盘（early spilled），以及下盘信息，包括重复下盘次数（spill Time(s)），内外表下盘分区数（inner/outer partition spill num），下盘文件数（temp file num），下盘数据量及最小和最大分区的下盘数据量（written disk IO [min, max] ）。

4. Targetlist Information (identified by plan id)

   这一部分显示的是每一个算子输出的目标列。

5. DataNode Information (identified by plan id)：

   这一部分会将各个算子的执行时间、CPU、buffer的使用情况全部打印出来。

6. User Define Profiling

   这一部分显示的是CN和DN、DN和DN建连的时间，以及存储层的一些执行信息。

7. ====== Query Summary =====：

   这一部分主要打印总的执行时间和网络流量，包括了各个DN上初始化和结束阶段的最大最小执行时间、CN上的初始化、执行、结束阶段的时间，以及当前语句执行时系统可用内存、语句估算内存等信息。

   须知：

   • A-rows和E-rows的差异体现了优化器估算和实际执行的偏差度。一般来说，偏差越大优化器生成的计划越不可信，人工干预调优的必要性越大。
   • A-time中的两个值偏差越大，表明此算子的计算偏斜(在不同DN上执行时间差异)越大，人工干预调优的必要性越大。
   • Max Query Peak Memory经常用来估算SQL语句耗费内存，也被用来作为SQL语句调优时运行态内存参数设置的重要依据。一般会以EXPLAIN ANALYZE或EXPLAIN PERFORMANCE的输出作为进一步调优的输入。