GBase 8a集群开启集群层日志查看每个阶段的耗时

GBase 8a数据库集群,可以通过开启详细日志级别,查看在SQL整个过程的耗时情况,包括执行计划,下发,返回结果给客户端等。

1.1.1.    作用

记录集群层SQL的完整执行过程,包括锁,对外交互(比如ftp加载),执行计划等,重点过程上。具体的SQL执行,内部资源消耗,还得看trc日志。

1.1.2.    使用方法

使用集群客户端 gccli

// 默认值是3,这个是session级别的,无需恢复

gbase> set gcluster_log_level=7;

// 日志级别更细

gbase> set global gbase_sql_trace_level=15;

// 打开日志

gbase> set gbase_sql_trace=1;

第一个参数是设置集群层日志的等级,包括锁,对外交互等。记录在express.log里。

第二个参数是SQL执行日志,记录在trc日志里。

第三个参数是设置打开和关闭跟踪日志,可以是session级的。 执行SQL语句后,在gcluster的log目录下的express.log里有详细的集群层调度日志。在gnode的log目录下生成执行计划每一步的具体SQL的trc结尾的日志。

express.log的样例。 里面可以根据[S:65][Q:274] 进行过滤。S代表sessionID, 而Q是queryid也就是每个查询有不同的编号(taskid)。

一个session可以执行多个任务,其SessionID相同,但QueryId不同。

gbase> set gcluster_log_level=7;
Query OK, 0 rows affected (Elapsed: 00:00:00.00)

gbase> select id,count(*) from testdb.t1 group by id;
+--------+----------+
| id     | count(*) |
+--------+----------+
| 111111 |        1 |
+--------+----------+
1 row in set (Elapsed: 00:00:00.05)


2020-11-06 17:49:39.972 [EXEC_P][INFO ][S:65][Q:274]:Original SQL:
2020-11-06 17:49:39.972 [EXEC_P][INFO ][S:65][Q:274]:##############################
2020-11-06 17:49:39.972 [EXEC_P][INFO ][S:65][Q:274]:#### Main Query Begin ####
2020-11-06 17:49:39.972 [EXEC_P][INFO ][S:65][Q:274]:##############################
2020-11-06 17:49:39.972 [EXEC_P][INFO ][S:65][Q:274]:---Top plan is [0x512e2e0]---
2020-11-06 17:49:39.972 [EXECTR][INFO ][S:65][Q:274]:Involved in 1 distribuitons
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Selected a random coordinator node: 10.0.2.102
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Coordinator node is 10.0.2.102
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:--#--Begin a async API mode--#--
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:A plan Begin ...
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Current plan [0x512e2e0] has 0 scalar subquery.
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Current plan [0x512e2e0] has 0 from subquery.
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Current plan [0x512e2e0] has 0 union subquery.
2020-11-06 17:49:39.973 [EXEC_P][INFO ][S:65][Q:274]:Current plan [0x512e2e0] has 2 steps.
2020-11-06 17:49:39.973 [EXEC_P][INFO ][S:65][Q:274]:## STEP: 0 ...
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Current plan [0x512e2e0] has 0 uncorrelated subquery.
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Distribution Info, /[8a:P1C1]
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:---Step detail: hash redistribute the table in gbase.
2020-11-06 17:49:39.973 [EXECTR][INFO ][S:65][Q:274]:Passed tasks to async API, good luck!
2020-11-06 17:49:39.974 [EXECTR][INFO ][S:65][Q:274]:AsyncAPI connect success!
2020-11-06 17:49:39.974 [SQLDISP][INFO ][S:65][Q:274]:Target:10.0.2.102, SQL:CREATE TABLE `gctmpdb`._tmp_rht_1711407114_65_t30_1_1604624808_s_n1 AS SELECT /*10.0.2.102_65_87_2020-11-06_17:49:39*/ /*+ TID('1048772') */ `testdb.t1`.`id` AS `c1`, COUNT(0) AS `c2` FROM `testdb`.`t1_n1` `testdb.t1` GROUP BY `testdb.t1`.`id` LIMIT 0 ; commit.
2020-11-06 17:49:39.980 [EXECTR][INFO ][S:65][Q:274]:
2020-11-06 17:49:39.980 [EXECTR][INFO ][S:65][Q:274]:Passed tasks to async API, good luck!
2020-11-06 17:49:39.981 [EXECTR][INFO ][S:65][Q:274]:AsyncAPI connect success!
2020-11-06 17:49:39.984 [SQLDISP][INFO ][S:65][Q:274]:Target:10.0.2.102, SQL:SELECT /*10.0.2.102_65_87_2020-11-06_17:49:39*/ /*+ TID('1048772') */ `testdb.t1`.`id` AS `c1`, COUNT(0) AS `c2` FROM `testdb`.`t1_n1` `testdb.t1` GROUP BY `testdb.t1`.`id` target into server (HOST '10.0.2.102', PORT 5050, USER 'root', PASSWORD '', DATABASE 'gctmpdb', TABLE '_tmp_rht_1711407114_65_t30_1_1604624808_s_n1', COMMENT 'group 0, distribution 1, hash_map 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
2020-11-06 17:49:40.014 [EXECTR][INFO ][S:65][Q:274]:
2020-11-06 17:49:40.014 [EXECTR][INFO ][S:65][Q:274]:Passed tasks to async API, good luck!
2020-11-06 17:49:40.015 [EXECTR][INFO ][S:65][Q:274]:AsyncAPI connect success!
2020-11-06 17:49:40.015 [SQLDISP][INFO ][S:65][Q:274]:Target:10.0.2.102, SQL:flush temporary commit `gctmpdb`._tmp_rht_1711407114_65_t30_1_1604624808_s_n1.
2020-11-06 17:49:40.017 [EXECTR][INFO ][S:65][Q:274]:
2020-11-06 17:49:40.018 [EXEC_P][INFO ][S:65][Q:274]:## STEP: 1 ...
2020-11-06 17:49:40.018 [EXECTR][INFO ][S:65][Q:274]:Current plan [0x512e2e0] has 0 uncorrelated subquery.
2020-11-06 17:49:40.018 [EXECTR][INFO ][S:65][Q:274]:Distribution Info, /[8a:P1]
2020-11-06 17:49:40.018 [EXECTR][INFO ][S:65][Q:274]:---Step detail: 8a to client, query to all gnode
2020-11-06 17:49:40.018 [EXECTR][INFO ][S:65][Q:274]:Passed tasks to async API, good luck!
2020-11-06 17:49:40.018 [EXECTR][INFO ][S:65][Q:274]:AsyncAPI connect success!
2020-11-06 17:49:40.018 [SQLDISP][INFO ][S:65][Q:274]:Target:10.0.2.102, SQL:SELECT /*10.0.2.102_65_87_2020-11-06_17:49:39*/ /*+ TID('1048772') */ `_tmp_rht_1711407114_65_t30_1_1604624808_s_n1`.`c1` AS `id`, cast(SUM_2ND(`_tmp_rht_1711407114_65_t30_1_1604624808_s_n1`.`c2`) as signed) AS `count(*)` FROM `gctmpdb`._tmp_rht_1711407114_65_t30_1_1604624808_s_n1 GROUP BY `_tmp_rht_1711407114_65_t30_1_1604624808_s_n1`.`c1`.
2020-11-06 17:49:40.020 [EXECTR][INFO ][S:65][Q:274]:Sent Rows: 1
2020-11-06 17:49:40.020 [EXECTR][INFO ][S:65][Q:274]:
2020-11-06 17:49:40.020 [EXECTR][INFO ][S:65][Q:274]:Finish all steps of plan [0x512e2e0].
2020-11-06 17:49:40.020 [EXECTR][INFO ][S:65][Q:274]:Passed tasks to async API, good luck!
2020-11-06 17:49:40.020 [EXECTR][INFO ][S:65][Q:274]:AsyncAPI connect success!
2020-11-06 17:49:40.020 [SQLDISP][INFO ][S:65][Q:274]:Target:10.0.2.102, SQL:DROP TABLE IF EXISTS `gctmpdb`._tmp_rht_1711407114_65_t30_1_1604624808_s_n1.
2020-11-06 17:49:40.021 [EXECTR][INFO ][S:65][Q:274]: