GaussDB T 性能调优——SQL问题分析之CBO trace 日志

CBO trace 日志

CBO trace日志记录了执行计划生成的过程。通过这个日志，可以得知为何会选择该执
行计划。

● 日志打开方式
开启后若在两分钟之内没有执行SQL语句，则自动关闭。

ALTER SESSION ENABLE optinfo_log;

● 日志保存路径
{$GSDB_DATA}/log/opt/

● 日志查看方法
每行以“INFO>”为分界，前面的都是公共的信息，其中时间信息方便查看该日志的生成时间。
主要的信息都在INFO之后。第一行以Begin create DML plan开始，后面记录了生成该日志的SQL语句。

单表日志

单表的日志中，主要描述了表扫描的方式，分为非索引和索引扫描两类。

● 非索引扫描
以下图中的日志信息为例，INFO之后，中括号中的内容一般为两种：idx-eval和
full-scan。

|INFO>[idx-eval]: starting, tab_id=0, name=HASH_TABLE1, idx_cnt=1, cbÑȎfl†gɊ3Ȁ parent_join=0, 
is_push_down=0 [plan_cbo.c:5649]
|INFO>[full-scan]: table[HASH_TABLE1], rows=4001, card=27, part_id=4294967295, blocks=22, 
e_blokcs=4, cost=32.002 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan cost=32.002 [plan_cbo.c:3755]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan chosen [plan_cbo.c:5604]

– 第1行，找到starting，后面tab_id表示表ID，name为表名，idx_cnt表示表中索引的数量，cbo_flog表示CBO的标志。

– 第2行，格式为table[表名]，rows表示表的总数据量，card是估算的返回的数据量，pard_id表示分区表的ID，blocks表示统计信息表占据的数据块的数量，e_blocks表示统计信息表占据的空块的数量，cost表明代价。

– 第3行，输出了全表扫描的代价。

– 第4行，说明选择了何种表扫描方式。

● 索引扫描

|INFO>[idx-eval]: starting, tab_id=0, name=EXPLAIN_PLAN, idx_cnt=3, cbÑȎfl†gɊ3Ȁ parent_join=0, 
is_push_down=0 [plan_cbo.c:5649]
|INFO>[idx-eval]: idx[1,IX_F1] - b_level=1, l_block=1, e_block=0, key_len=0.143, ²šxȎÃbÀȎffɊ1ȇ000Ȁ
݆rìȎffɊ1ȇ000Ȁ matched_cnt=1, blocks=1, rows=12, cf=1, ffɊ0ȇ250000000Ȁ cf_factor=1.000, 
cost=5.507500, äc†nȎfl†gɊ0Ȁ parted=0, part_no=4294967295 [plan_cbo.c:4695]
|INFO>[idx-eval]: idx[1,IX_F1] - total_cost=5.508 [plan_cbo.c:4734]
|INFO>[idx-eval]: idx[2,IX_F1F2] - b_level=1, l_block=1, e_block=0, key_len=0.083, ²šxȎÃbÀȎffɊ1ȇ000Ȁ
݆rìȎffɊ1ȇ000Ȁ matched_cnt=1, blocks=1, rows=12, cf=1, ffɊ0ȇ250000000Ȁ cf_factor=1.000, 
cost=5.507500, äc†nȎfl†gɊ0Ȁ parted=0, part_no=4294967295 [plan_cbo.c:4695]
|INFO>[idx-eval]: idx[2,IX_F1F2] - total_cost=5.508 [plan_cbo.c:4734]
|INFO>[idx-eval]: choose optimal index[1,IX_F1], äc†nȎfl†gɊ0Ȁ idx_dsc=0, cost=5.508 [plan_cbo.c:5673]
|INFO>[full-scan]: table[EXPLAIN_PLAN], rows=12, card=3, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.030 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[EXPLAIN_PLAN] - full scan cost=6.030 [plan_cbo.c:3755]
|INFO>[idx-eval]: fin²ä¯ choose optimal index[1,IX_F1], äc†nȎfl†gɊ0Ȁ idx_dsc=0, index_skip_scan=0 
[plan_cbo.c:5700]

索引有关的日志如下：

索引扫描的日志中，会添加索引的相关信息。
– 以上述第2行为例，记录了索引ID和索引名称及其他相关信息。

idx[ID,IDX_NAME] - b_level=1, l_block=1, e_block=0, key_len=0.143, ²šxȎÃbÀȎffɊ1ȇ000Ȁ
݆rìȎffɊ1ȇ000Ȁ matched_cnt=1, blocks=1, rows=12, cf=1, ffɊ0ȇ250000000Ȁ cf_factor=1.000, 
cost=5.507500, äc†nȎfl†gɊ0Ȁ parted=0, part_no=4294967295 [plan_cbo.c:4695]

▪ b_level：索引深度。
▪ l_block：叶子块个数。
▪ e_block：空叶子块个数。
▪ key_len：每个关键字的平均叶子数。
▪ idx_lbk_ff：叶子块过滤因子。
▪ part_ff：分区表的过滤因子。
▪ matched_cnt：索引匹配的个数。
▪ cf：聚集因子。
▪ ff：过滤因子。
▪ cf_factor：聚簇因子参数。
▪ scan_flag：索引扫描标志。
▪ parted：分区数。
▪ part_no：分区号。

– 上述索引日志中的最后一行，完成选择最佳索引。

finish choose optimal index[1,IX_F1], scan_flag=o, idx_dsc=0, index_skip_scan=0 [plan_cbo.c:5700]

▪ scan_flag：表扫描的标志。
▪ idx_dsc：索引扫描的方向。
▪ index_skip_scan：标志是否是索引跳跃扫描。

多表日志

多表关联的CBO trace日志中，除了包含上述单表的流程之外，还包含了选择驱动表的过程。

|INFO>[driver count]: TOP-N get driver_table_count=12 [plan_cbo.c:8972]
|INFO>[idx-eval]: starting, tab_id=0, name=T1, idx_cnt=1, cbo_flag=3, parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[full-scan]: table[HASH_TABLE1], rows=4001, card=4001, part_id=4294967295, blocks=22, 
e_blokcs=4, cost=32.002 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan cost=32.002 [plan_cbo.c:3755]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan chosen [plan_cbo.c:5604]
|INFO>[full-scan]: table[HASH_TABLE1], rows=4001, card=4001, part_id=4294967295, blocks=22, 
e_blokcs=4, cost=32.002 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan cost=32.002 [plan_cbo.c:3755]
|INFO>[idx-eval]: starting, tab_id=1, name=T2, idx_cnt=1, cbo_flag=2;parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_2] - PK full matched, cbo_flags=2, col_flags=2, has_parent_join=0 
[plan_cbo.c:4862]
|INFO>[idx-eval]: driver table[0_(0,0)] - empty_stats[0], tab_card=4001, tab_out_card=4001, 
driver_card=4001 [plan_cbo.c:4275]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_2] - idx_column-matched(1,1,1->1), c1_ndv=101, c2_ndv=0, c3_ndv=0, 
c4_ndv=0, all_ndv=101, flag=(2,2) [plan_cbo.c:4153]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_2] - comb_card=4001, ndv=101 [plan_cbo.c:4326]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_2] - b_level=1, l_block=1, e_block=0, key_len=0.010, idx_lbk_ff=1.000,
part_ff=1.000, matched_cnt=1, blocks=1, rows=101, cf=1, ff=39.613861386,cf_factor=1.000, 
cost=212.071807, scan_flag=0, parted=0, part_no=4294967295 [plan_cbo.c:4695]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_2] - total_cost=212.072 [plan_cbo.c:4734]

|INFO>[idx-eval]: choose optimal index[0,_PK_SYS_30_2], scan_flag=0, idx_dsc=0, cost=212.072 [plan_cbo.c:
5673]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan condition not matched, can_use_idx=1, flag=1,
has_parent_join=0 [plan_cbo.c:5684]
|INFO>[idx-eval]: fin²ä¯ choose optimal index[0,_PK_SYS_30_2], scan_flag=o,idx_dsc=0, index_skip_scan=0 
[plan_cbo.c:5700]
|INFO>>>> Start Choose Edge(0 --> 1) [oper=1, join_index=(_PK_SYS_30_2,0), l_index=NULL, 
in_card=(4001,101), in_cost=(32.002,212.072), cost=244.074] [plan_cbo.c:8429]
|INFO>[idx-eval]: starting, tab_id=1, name=T2, idx_cnt=1, cbo_flag=1,parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[full-scan]: table[HASH_TABLE2], rows=101, card=101, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.253 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan cost=6.253 [plan_cbo.c:3755]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan chosen [plan_cbo.c:5604]
|INFO>[full-scan]: table[HASH_TABLE2], rows=101, card=101, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.253 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan cost=6.253 [plan_cbo.c:3755]
|INFO>[join-edge]: oper=5, rate=1.000, in_card=(4001,101), in_cost=(32.002,6.253), cost=244.074, 
cur_cost=89.782 [plan_cbo.c:8452]
|INFO>[join selectivity]: l_selty=1.000000000, r_selty=1.000000000, NDV=(4001, 101), 
cur_selty=0.000249938 [plan_cbo.c:7439]
|INFO>[join selectivity]: table join [(0, 0)--(1, 0)], cur_selty=0.000249938, join_selty=0.000249938, 
card=404101, cartesian_card=404101 [plan_cbo.c:8121]
|INFO>[join selectivity]: table join card after adjust [(0 --> 1), join_selty=0.000249938, in_card=404101, 
out_card=101] [plan_cbo.c:8135]
|INFO>>>> Finish Choose Optimized Edge[(0,1), oper=5, in_card=(4001,101), out_card=101, 
in_cost=89.782, out_cost=90.035] [plan_cbo.c:8494]
|INFO>>>>>> Start Graph Djkstra Path, Start Node[tab=0] [plan_cbo.c:8768]
|INFO>[join selectivity]: l_selty=1.000000000, r_selty=1.000000000, NDV=(4001, 101), 
cur_selty=0.000249938 [plan_cbo.c:7439]
|INFO>[join selectivity]: table join [(0, 0)--(1, 0)], cur_selty=0.000249938, join_selty=0.000249938, 
card=404101, cartesian_card=404101 [plan_cbo.c:8121]
|INFO>[join selectivity]: table join card after adjust [(0 --> 1), join_selty=0.000249938, in_card=404101, 
out_card=101] [plan_cbo.c:8135]
|INFO>>>> Save join node[1] with edge[(0,1), oper=(5,1), graph_card=101, edge_cost=90.035, total 
cost=90.035] [plan_cbo.c:8707]
|INFO>>>> Graph Table Cost=90.035, Path=T[0]-->T[1] [plan_cbo.c:6638]
|INFO>>>> Graph Table Cost Path: T(T1)-->T(T2)[5, 90.035] [plan_cbo.c:6666]
|INFO>-------------------------------------------------------------------------------------- [plan_cbo.c:6667]
|INFO>[idx-eval]: starting, tab_id=1, name=T2, idx_cnt=1, cbÑȎfl†gɊ3Ȁ parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[full-scan]: table[HASH_TABLE2], rows=101, card=101, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.253 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan cost=6.253 [plan_cbo.c:3755]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan chosen [plan_cbo.c:5604]
|INFO>[full-scan]: table[HASH_TABLE2], rows=101, card=101, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.253 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan cost=6.253 [plan_cbo.c:3755]
|INFO>[idx-eval]: starting, tab_id=0, name=T1, idx_cnt=1, cbo_flag=2,parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_1] - PK full matched, cbo_flag=2,col_flags=2, has_parent_join=0 
[plan_cbo.c:4862]
|INFO>[idx-eval]: driver table[0_(1,0)] - empty_stats[0], tab_card=101, tab_out_card=101, driver_card=101 
[plan_cbo.c:4275]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_1] - idx_column-matched(1,1,1->1), c1_ndv=4001, c2_ndv=0, c3_ndv=0, 
c4_ndv=0, all_ndv=4001, flags(2,2) [plan_cbo.c:4153]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_1] - comb_card=101, ndv=4001 [plan_cbo.c:4326]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_1] - b_level=2, l_block=9, e_block=0, key_len=0.002,idx_lbk_ff=1.000,
part_ff=1.000, matched_cnt=1, blocks=22, rows=4001, cf=18, ff=0.025243689,cf_factor=1.000, 
cost=9.615659, scan_flag=0, parted=0, part_no=4294967295 [plan_cbo.c:4695]
|INFO>[idx-eval]: idx[0,_PK_SYS_30_1] - total_cost=9.616 [plan_cbo.c:4734]
|INFO>[idx-eval]: choose optimal index[0,_PK_SYS_30_1], 
scan_flag=0,idx_dsc=0, cost=9.616 [plan_cbo.c:
5673]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan condition not matched, can_use_idx=1, flag=1,
has_parent_join=0 [plan_cbo.c:5684]
|INFO>[idx-eval]: fin²ä¯ choose optimal index[0,_PK_SYS_30_1], scan_flag=0, idx_dsc=0, index_skip_scan=0 
[plan_cbo.c:5700]
|INFO>>>> Start Choose Edge(1 --> 0) [oper=1, join_index=(_PK_SYS_30_1,0), l_index=NULL, 
in_card=(101,4001), in_cost=(6.253,9.616), cost=15.868] [plan_cbo.c:8429]

|INFO>[idx-eval]: starting, tab_id=0, name=T1, idx_cnt=1, cbo_flag=1, parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[full-scan]: table[HASH_TABLE1], rows=4001, card=4001, part_id=4294967295, blocks=22, 
e_blokcs=4, cost=32.002 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan cost=32.002 [plan_cbo.c:3755]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan chosen [plan_cbo.c:5604]
|INFO>[full-scan]: table[HASH_TABLE1], rows=4001, card=4001, part_id=4294967295, blocks=22, 
e_blokcs=4, cost=32.002 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE1] - full scan cost=32.002 [plan_cbo.c:3755]
|INFO>[join-edge]: oper=5, rate=1.000, in_card=(101,4001), in_cost=(6.253,32.002), cost=15.868, 
cur_cost=89.782 [plan_cbo.c:8452]
|INFO>[join selectivity]: l_selty=1.000000000, r_selty=1.000000000, NDV=(101, 4001), 
cur_selty=0.000249938 [plan_cbo.c:7439]
|INFO>[join selectivity]: table join [(1, 0)--(0, 0)], cur_selty=0.000249938, join_selty=0.000249938, 
card=10443, cartesian_card=10443 [plan_cbo.c:8121]
|INFO>[join selectivity]: table join card after adjust [(1 --> 0), join_selty=0.000249938, in_card=10443, 
out_card=2] [plan_cbo.c:8135]
|INFO>>>> Finish Choose Optimized Edge[(1,0), oper=1, in_card=(101,4001), out_card=2, in_cost=15.868, 
out_cost=15.873] [plan_cbo.c:8494]
|INFO>>>>>> Start Graph Djkstra Path, Start Node[tab=1] [plan_cbo.c:8768]
|INFO>[join selectivity]: l_selty=1.000000000, r_selty=1.000000000, NDV=(101, 4001), 
cur_selty=0.000249938 [plan_cbo.c:7439]
|INFO>[join selectivity]: table join [(1, 0)--(0, 0)], cur_selty=0.000249938, join_selty=0.000249938, 
card=10443, cartesian_card=10443 [plan_cbo.c:8121]
|INFO>[join selectivity]: table join card after adjust [(1 --> 0), join_selty=0.000249938, in_card=10443, 
out_card=2] [plan_cbo.c:8135]
|INFO>>>> Save join node[1] with edge[(1,0), oper=(1,1), graph_card=2, edge_cost=15.873, total 
cost=15.873] [plan_cbo.c:8707]
|INFO>>>>>> Generate optimal Graph [plan_cbo.c:9308]
|INFO>>>> Graph Table Cost=15.873, Path=T[1]-->T[0] [plan_cbo.c:6638]
|INFO>>>> Graph Table Cost Path: T(T2)-->T(T1)[1, 15.873] [plan_cbo.c:6666]
|INFO>-------------------------------------------------------------------------------------- [plan_cbo.c:6667]
|INFO>[join-tree]: >>> Begin create join tree[CNT=2, FT=HASH_TABLE1] [plan_cbo.c:9679]
|INFO>[idx-eval]: starting, tab_id=1, name=T2, idx_cnt=1, cbÑȎfl†gɊ3Ȁ parent_join=0, is_push_down=0 
[plan_cbo.c:5649]
|INFO>[full-scan]: table[HASH_TABLE2], rows=101, card=101, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.253 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan cost=6.253 [plan_cbo.c:3755]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan chosen [plan_cbo.c:5604]
|INFO>[full-scan]: table[HASH_TABLE2], rows=101, card=101, part_id=4294967295, blocks=1, e_blokcs=0, 
cost=6.253 [plan_cbo.c:3709]
|INFO>[idx-eval]: tab[HASH_TABLE2] - full scan cost=6.253 [plan_cbo.c:3755]
|INFO>[join selectivity]: l_selty=1.000000000, r_selty=1.000000000, NDV=(4001, 101), 
cur_selty=0.000249938 [plan_cbo.c:7439]
|INFO>[join-tree]: >>> End create join tree[CNT=2, FT=HASH_TABLE1] [plan_cbo.c:9725]
|INFO>-------------------------------------------------------------------------------------- [plan_cbo.c:9726]

紧接着SQL语句下面的一行，显示的是[driver count]，列出了驱动表的数量。这些表轮流做驱动表，然后找到其中代价最小的一种组合，根据这个组合构建join tree，根据生成的join tree生成最后的执行计划。

以Graph Table Cost Path为界，上面的内容都是选择路径的过程。每个表的扫描方式参照单表，表之间的连接方式，以Start Choose Edge开始，Finish Choose Optimized Edge结束。之间的内容，是选择连接方式的过程，oper这个参数，指明了表连接的方式，参数的值的含义如下：

说明
参数的值可能在旧版本有所不同，值可能为2^(n-1)(n为当前表格中的值) table join之后，是表之间关联字段的选择，形式为table join [tab_id, col_id) --(tab_id, col_id)]。

Graph Table Cost Path指明了表驱动的顺序、方式和代价，例如：

T1、T2为表的别名或表名，以HASH JOIN的方式连接，代价为90.035。下一步就是T2驱动T1，最后为：

可以看到，连接方式为NESTED LOOPS，代价为15.873。第二个的代价小，在下面构建join tree时，选择的第一个表将会是T2。

在轮流做完驱动表之后，会按最小代价构建join tree，其中会指明表的数量和第一个
表。日志以End create join tree结束。