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] ======================================================