openGauss 有一个慢 SQL 诊断特性，数据库会依据配置自动记录慢 SQL 执行过程中的诊断信息，提供表与函数两种查询接口。

相关 GUC 参数

  • log_min_duration_statement：慢 SQL 执行时间阈值。

    超过该时间的语句会被识别为慢 SQL 并依据配置记录诊断信息。

  • track_stmt_stat_level：语句诊断信息的记录级别。

    可为普通语句与慢 SQL 分别配置，用逗号分隔。 默认值为 OFF,L0，表示不记录普通语句，以 L0 级别记录慢 SQL 语句的诊断信息。

  • track_activity_query_size：慢 SQL 语句记录的最大长度，超过长度后会被截断。

查询诊断信息

首先建表，插入足够多的数据：

CREATE TABLE t (v integer);
INSERT INTO t VALUES (generate_series(1, 1E6));

可以打开计时功能，输出每条 SQL 的执行时间：

\timing on

默认的慢 SQL 阈值是 30 分钟，太久了，所以我们简单降低一下：

SET log_min_duration_statement TO '100ms';

于是对之前的表做全表扫描输出，因为结果比较多，可以将输出重定向到 /dev/null：

\o /dev/null
SELECT * from t;
\o

由于诊断信息的字段很多，一般是先给 gsql 开启 expanded 输出模式：

\pset expanded on

查询所有诊断信息：

SELECT * FROM dbe_perf.statement_history;

介绍一些常用字段：

  • query：经过脱敏处理的原始语句
  • start_time：执行开始时间
  • finish_time：执行结束时间
  • query_plan：执行计划
  • n_returned_rows：返回行数
  • details：bytea 类型，记录语句执行中的等待事件，可使用 statement_detail_decode 解析

访问的元组与块：

  • n_tuples_fetched
  • n_tuples_returned
  • n_tuples_inserted
  • n_tuples_updated
  • n_tuples_deleted
  • n_blocks_fetched
  • n_blocks_hit

各类耗时：

  • db_time
  • cpu_time
  • execution_time
  • parse_time
  • plan_time
  • rewrite_time
  • pl_execution_time
  • pl_compilation_time
  • data_io_time

清除诊断信息：

DELETE FROM dbe_perf.statement_history;

查询慢 SQL 中的等待事件

构造数据：

CREATE TABLE t (v integer);
INSERT INTO t VALUES (1);

开启事务修改该表中的数据，但不提交：

BEGIN;
UPDATE t SET v = 1 where v = 1;

在新会话中再次修改该数据，会被阻塞：

SET log_min_duration_statement TO '100ms';

UPDATE t SET v = 1 where v = 1;

等待一段时间后在原会话中结束事务：

END;

最后通过全局函数 statement_detail_decode 解析 details 列中的等待事件信息：

\pset expanded on

SELECT *, statement_detail_decode(details, 'plaintext', true) FROM dbe_perf.statement_history;

可以看到最后有类似这样的输出：

statement_detail_decode |         ---------------Wait Events Area--------------- 
                        | '1'     LOCK_EVENT      transactionid                                      4061898 (us)
                        | '2'     STATUS          flush data                                              11 (us)
                        | '3'     IO_EVENT        BufHashTableSearch                                       9 (us)
                        | '4'     IO_EVENT        WALBufferAccess                                          0 (us)

其中 transactionid 类型的 LOCK_EVENT 就是不同会话并发修改同一条数据导致的等待事件。

查询全局范围的等待事件

在一些 OLTP 的基准测试场景下，执行事务的频率很高，且每条语句的执行时间都很短，逐条分析是比较困难的。 这时就可以从全局范围查询等待事件进行观察：

SELECT * FROM dbe_perf.wait_events ORDER BY total_wait_time DESC;

如果 IO_EVENT 耗时较长，需要去关注磁盘相关的问题；如果是 LOCK_EVENT 则需要关注并发语句的竞争问题。