GBase 8a trace日志的作用

trace日志默认是关闭的。主要用于分析性能，当出现性能问题时，需临时打开trace日志查看SQL执行计划；

 可连上数据库，在数据库中执行set命令打开trace日志：

gbase>set global gbase_sql_trace=1;

gbase>set global gbase_sql_trace_level=3;

其中：gbase_sql_trace_level 有1、2、3级，表示trace日志记录信息的详细程度，第3级是最详细的日志内容。日志文件为.trc后缀名的文件中。

Trace日志是根据当前session连接生成的trc日志，故session断开，产生新的trc日志。由于日志内容较大，不方便分析，每次执行sql语句之前建议清空以前的trc日志文件，方法为使用 rm -rf *.trc 删除之前的trace日志。

gcluster层的trace记录SQL的分布式执行计划。可查看SQL语句的计划步骤是3步还是2步，找出执行时间间隔最大的步骤，然后分析是否能应用优化方法进行优化提高性能。

Gnode层的trace日志记录SQL语句的完整执行过程。因为一条SQL语句经gcluster层解析分解执行计划后，会产生很多条SQL语句下发到gnode层，所以在gnode的日志目录下会产生多个.trc日志文件，建议查看执行节点的gnode层的字节数最大的那个.trc文件即可。

注意说明：

 trace日志内容很多，开启trace日志会对执行性能产生影响，而且不方便分析，建议在执行sql语句之前清空原日志（或者备份原日志后再清空）。

方法为：每次执行sql前，要使用 rm -rf *.trc 清空之前的trace日志。

 技术支持人员无法分析时，可将gcluster层和gnode层的trace日志打包，发送给研发人员做进一步分析。

示例：

[gbase@node37 gbase]$ cat  gbase_root_168_20221124111233.trc

/opt/192.168.100.37/gnode/log/gbase/gbase_root_168_20221124111233.trc

Server Version: 9.5.3.28.2b9c8b44

Version Comment: 2b9c8b44

Instance Name: gbase

Session ID: 168

User: root

Time: 20221124111233

GBASE_HOME=/opt/192.168.100.37/gnode/server/

CPUS: 4

MEM:  15543 MB

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] before opt:select count(1) AS "COUNT(1)" from "tpch"."lineitem_n1" "vcname000001.tpch.lineitem"

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] after  opt:select count(1) AS "COUNT(1)" from "tpch"."lineitem_n1" "vcname000001.tpch.lineitem"

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] SQL Statement:

SELECT  COUNT(1) FROM `tpch`.`lineitem_n1`  `vcname000001.tpch.lineitem`

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] Start Query Execution

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 6001215, attr count = 1, record size = 8, page size = 6029312

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] BEGIN Serial Aggregation(6001215 rows)

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] BEGIN Aggregation(6001215 rows)

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] TempTable::MultiDimensionalGroupByScan(): aggregate 6001215 rows)

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:12:33.819 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:12:33.820 [M: 516K,   0B,D:   0B] [DC:     0,     0] END Serial Aggregation. (time used: 0.000s)

2022-11-24 11:12:33.820 [M: 516K,   0B,D:   0B] [DC:     1,     0] Send 1 rows already

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 65536, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] ResultSender: send 0 rows.

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] output result done.

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] SUMMARY

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] elapsed time:                00:00:00.001

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] data loaded from storage:       0B,  0s,     0 DC.

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] data decompressed:              0B,  0s.

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] temp space IO stats:

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] CB   write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] SRT  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] GDC  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] MAT  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] HSJ  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:12:33.820 [M: 112B,   0B,D:   0B] [DC:     1,     0] ======================================================

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     1,     0] before opt:select count(1) AS "COUNT(1)" from "tpch"."customer_n1" "vcname000001.tpch.customer"

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     1,     0] after  opt:select count(1) AS "COUNT(1)" from "tpch"."customer_n1" "vcname000001.tpch.customer"

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] SQL Statement:

SELECT  COUNT(1) FROM `tpch`.`customer_n1`  `vcname000001.tpch.customer`

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] Start Query Execution

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 150000, attr count = 1, record size = 8, page size = 196608

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] BEGIN Serial Aggregation(150000 rows)

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] BEGIN Aggregation(150000 rows)

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:17.726 [M: 112B,   0B,D:   0B] [DC:     0,     0] TempTable::MultiDimensionalGroupByScan(): aggregate 150000 rows)

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:15:17.727 [M: 516K,   0B,D:   0B] [DC:     0,     0] END Serial Aggregation. (time used: 0.001s)

2022-11-24 11:15:17.727 [M: 516K,   0B,D:   0B] [DC:     1,     0] Send 1 rows already

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 65536, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] ResultSender: send 0 rows.

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] output result done.

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] SUMMARY

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] elapsed time:                00:00:00.001

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] data loaded from storage:       0B,  0s,     0 DC.

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] data decompressed:              0B,  0s.

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] temp space IO stats:

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] CB   write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:17.727 [M: 112B,   0B,D:   0B] [DC:     1,     0] SRT  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:17.728 [M: 112B,   0B,D:   0B] [DC:     1,     0] GDC  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:17.728 [M: 112B,   0B,D:   0B] [DC:     1,     0] MAT  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:17.728 [M: 112B,   0B,D:   0B] [DC:     1,     0] HSJ  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:17.728 [M: 112B,   0B,D:   0B] [DC:     1,     0] ======================================================

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     1,     0] before opt:select count(1) AS "COUNT(1)" from "tpch"."orders_n1" "vcname000001.tpch.orders"

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     1,     0] after  opt:select count(1) AS "COUNT(1)" from "tpch"."orders_n1" "vcname000001.tpch.orders"

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] SQL Statement:

SELECT  COUNT(1) FROM `tpch`.`orders_n1`  `vcname000001.tpch.orders`

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] Start Query Execution

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1500000, attr count = 1, record size = 8, page size = 1507328

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] BEGIN Serial Aggregation(1500000 rows)

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:38.779 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     0,     0] BEGIN Aggregation(1500000 rows)

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     0,     0] GTBuff: total_size:134217728 has_dist:0 rows_limit:1 width:8

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     0,     0] TempTable::MultiDimensionalGroupByScan(): aggregate 1500000 rows)

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     0,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 1, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:15:38.780 [M: 516K,   0B,D:   0B] [DC:     0,     0] END Serial Aggregation. (time used: 0.001s)

2022-11-24 11:15:38.780 [M: 516K,   0B,D:   0B] [DC:     1,     0] Send 1 rows already

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] CalculatePageSize: TmpCacheSize = 67108864, no obj = 65536, attr count = 1, record size = 8, page size = 65536

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] ResultSender: send 0 rows.

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] output result done.

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] SUMMARY

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] elapsed time:                00:00:00.001

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] data loaded from storage:       0B,  0s,     0 DC.

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] data decompressed:              0B,  0s.

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] temp space IO stats:

2022-11-24 11:15:38.780 [M: 112B,   0B,D:   0B] [DC:     1,     0] CB   write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:38.781 [M: 112B,   0B,D:   0B] [DC:     1,     0] SRT  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:38.781 [M: 112B,   0B,D:   0B] [DC:     1,     0] GDC  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:38.781 [M: 112B,   0B,D:   0B] [DC:     1,     0] MAT  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:38.781 [M: 112B,   0B,D:   0B] [DC:     1,     0] HSJ  write(   0B, 0time, 0sec),       read(   0B, 0time, 0sec)

2022-11-24 11:15:38.781 [M: 112B,   0B,D:   0B] [DC:     1,     0] ======================================================