运维首页 > 数据运维 > opengauss/Mogdb SQL性能分析之statement_history

opengauss/Mogdb SQL性能分析之statement_history

2023年 11月 29日 112.6k 0

原作者：范计杰

概述

概述statement_history用于记录当前节点的SQL执行信息，用于替代日志方式记录Slow SQL。用于性能问题定位、SQL性能问题分析。会根据配置，记录两类SQL。

  • 全量SQL记录
  • 慢SQL

对于此系统表查询有如下约束：

  • 必须在postgres库内查询，其它库中不存数据。
  • 此系统表受track_stmt_stat_level控制，默认为"OFF,L0"，第一部分控制Full SQL，第二部分控制Slow SQL，具体字段记录级别见下表。
  • 对于Slow SQL，当track_stmt_stat_level的值为非OFF时，且SQL执行时间超过log_min_duration_statement，会记录为慢SQL。
  • 查询系统表必须具有sysadmin权限。

相关参数

  • log_min_duration_statement
    参数说明：设置记录慢SQL的阀值。默认值1800000ms

-1 is disabled, 0 logs all statements and their durations, > 0 logs only statements running at least this number of milliseconds

  • track_stmt_details_size
    参数说明：设置单语句可以收集的最大的执行事件的大小(byte)。

该参数属于USERSET类型参数，请参考重设参数中对应设置方法进行设置。

取值范围：整型，0 ~ 576460752303423487

默认值：4096

  • track_stmt_retention_time
    参数说明：组合参数，控制全量/慢SQL记录的保留时间。以60秒为周期读取该参数，并执行清理超过保留时间的记录，仅sysadmin用户可以访问。

该参数属于SIGHUP类型参数，请参考重设参数中对应设置方法进行设置。

取值范围：字符型

该参数分为两部分，形式为’full sql retention time, slow sql retention time’：

full sql retention time为全量SQL保留时间，取值范围为0 ~ 86400。
slow sql retention time为慢SQL的保留时间，取值范围为0 ~ 604800。
默认值：3600,604800

  • track_stmt_stat_level
    参数说明：控制语句执行跟踪的级别。

该参数属于USERSET类型参数，请参考重设参数中对应设置方法进行设置，不区分英文字母大小写，如果打开full sql功能会影响性能，并可能会占用大量的磁盘空间。

取值范围：字符型

该参数分为两部分，形式为’full sql stat level, slow sql stat level’：

第一部分为全量SQL跟踪级别，取值范围为OFF、L0、L1、L2。
第二部分为慢SQL的跟踪级别，取值范围为OFF、L0、L1、L2。

说明：
若全量SQL跟踪级别值为非OFF时，当前SQL跟踪级别值为全量SQL和慢SQL的较高级别（L2 > L1 >L0），级别说明请参见表1。

默认值：OFF,L0

  • track_stmt_parameter
    Enable to track the parameter of statements，默认值OFF

相关函数

  • statement_detail_decode(detail text, format text, pretty boolean)
    描述：解析全量/慢SQL语句中的details字段的信息。
    返回值类型：text
    参数
    detail: SQL语句产生的事件的集合（不可读）。
    format: 解析输出格式，取值为plaintext。
    pretty: 当format为plaintext时，是否以优雅的格式展示：
    true表示通过“\n”分隔事件。
    false表示通过“，”分隔事件。

示例，查看SQL执行过程中锁申请、释放信息

select unique_query_id,statement_detail_decode(details,'plaintext',true) from statement_history where details is not null;

unique_query_id | statement_detail_decode
-----------------+----------------------------------------------------------------------------------------------------------------
3809144128 | '1' 'LOCK_START' '2022-05-18 10:16:03.309549+08' '3e44:a37:0:0:0:0' 'AccessShareLock' +
| '2' 'LOCK_END' '2022-05-18 10:16:03.309557+08' +
| '3' 'LOCK_START' '2022-05-18 10:16:03.309565+08' '3e44:a7c:0:0:0:0' 'AccessShareLock' +
| '4' 'LOCK_END' '2022-05-18 10:16:03.309566+08' +
| '5' 'LOCK_RELEASE' '2022-05-18 10:16:03.309581+08' '3e44:a7c:0:0:0:0' 'AccessShareLock' +
| '6' 'LOCK_RELEASE' '2022-05-18 10:16:03.309581+08' '3e44:a37:0:0:0:0' 'AccessShareLock' +
| '7' 'LOCK_START' '2022-05-18 10:16:03.309588+08' '3e44:30c8:0:0:0:0' 'AccessShareLock' +
| '8' 'LOCK_END' '2022-05-18 10:16:03.309589+08' +
| '9' 'LOCK_START' '2022-05-18 10:16:03.309625+08' '3e44:21c3:0:0:0:0' 'AccessShareLock' +
| '10' 'LOCK_END' '2022-05-18 10:16:03.309625+08' +
| '11' 'LOCK_START' '2022-05-18 10:16:03.309629+08' '3e44:21cc:0:0:0:0' 'AccessShareLock' +
| '12' 'LOCK_END' '2022-05-18 10:16:03.309629+08' +
| '13' 'LOCK_RELEASE' '2022-05-18 10:16:03.309637+08' '3e44:21cc:0:0:0:0' 'AccessShareLock' +
| '14' 'LOCK_RELEASE' '2022-05-18 10:16:03.309638+08' '3e44:21c3:0:0:0:0' 'AccessShareLock' +
| '15' 'LOCK_START' '2022-05-18 10:16:03.309676+08' '0:2337:0:0:0:0' 'AccessShareLock' +
| '16' 'LOCK_END' '2022-05-18 10:16:03.309676+08' +
| '17' 'LOCK_START' '2022-05-18 10:16:03.30968+08' '0:2340:0:0:0:0' 'AccessShareLock' +
| '18' 'LOCK_END' '2022-05-18 10:16:03.30968+08' +
| '19' 'LOCK_RELEASE' '2022-05-18 10:16:03.309691+08' '0:2340:0:0:0:0' 'AccessShareLock' +
| '20' 'LOCK_RELEASE' '2022-05-18 10:16:03.309691+08' '0:2337:0:0:0:0' 'AccessShareLock' +
| '21' 'LOCK_START' '2022-05-18 10:16:03.309707+08' '3e44:30c8:0:0:0:0' 'AccessShareLock' +
| '22' 'LOCK_END' '2022-05-18 10:16:03.309708+08' +
| '23' 'LOCK_START' '2022-05-18 10:16:03.309708+08' '3e44:30c8:0:0:0:0' 'AccessShareLock' +
| '24' 'LOCK_END' '2022-05-18 10:16:03.309708+08' +
| '25' 'LOCK_RELEASE' '2022-05-18 10:16:03.311669+08' '3e44:30c8:0:0:0:0' 'AccessShareLock'
2893388431 | '1' 'LOCK_START' '2022-05-18 10:16:13.312375+08' '0:4ec:0:0:0:0' 'AccessShareLock' +
| '2' 'LOCK_END' '2022-05-18 10:16:13.31239+08' +
| '3' 'LOCK_RELEASE' '2022-05-18 10:16:13.312412+08' '0:4ec:0:0:0:0' 'AccessShareLock'
2490934982 | '1' 'LOCK_START' '2022-05-18 10:16:26.869224+08' '0:4ec:0:0:0:0' 'AccessShareLock'

常见问题

1、占用多少内存
跑一下benchmarksql，测一下能会记录多少SQL，及内存占用情况

参数
track_stmt_stat_level | L0,L2

MogDB=# select is_slow_sql,count(*),min(start_time),min(finish_time),max(now()) now from statement_history group by is_slow_sql;
is_slow_sql | count | min | min | now
-------------+--------+-------------------------------+-------------------------------+-------------------------------
t | 5 | 2022-05-18 09:54:21.865765+08 | 2022-05-18 09:54:22.871032+08 | 2022-05-18 11:24:51.791587+08
f | 363794 | 2022-05-18 10:24:48.128899+08 | 2022-05-18 10:24:48.132055+08 | 2022-05-18 11:24:51.791587+08
(2 rows)

Time: 13947.234 ms
MogDB=# select * from global_shared_memory_detail where contextname like '%statement_history%';
node_name | contextname | level | parent | totalsize | freesize | usedsize
-----------+----------------------------+-------+-----------------------------------+-----------+----------+----------
test | statement_history_time_idx | 4 | GlobalSysDBCacheEntryMemCxt_15940 | 4096 | 272 | 3824
test | statement_history | 4 | GlobalSysDBCacheEntryMemCxt_15940 | 8432 | 112 | 8320
test | statement_history | 4 | GlobalSysDBCacheEntryMemCxt_16385 | 8432 | 112 | 8320
test | statement_history_time_idx | 4 | GlobalSysDBCacheEntryMemCxt_16385 | 4096 | 272 | 3824
(4 rows)

Time: 23.284 ms
记录的SQL 36万，相应的SQL内存区大小并没有变化，占用的内存很小，数据会记录到postgres.statement_history表中

MogDB=# \dS+ statement_history
Unlogged table "pg_catalog.statement_history"
Column | Type | Modifiers | Storage | Stats target | Description
----------------------+--------------------------+-----------+----------+--------------+-------------
db_name | name | | plain | |
schema_name | name | | plain | |
origin_node | integer | | plain | |
user_name | name | | plain | |
application_name | text | | extended | |
client_addr | text | | extended | |
client_port | integer | | plain | |
unique_query_id | bigint | | plain | |
debug_query_id | bigint | | plain | |
query | text | | extended | |
start_time | timestamp with time zone | | plain | |
finish_time | timestamp with time zone | | plain | |
slow_sql_threshold | bigint | | plain | |
transaction_id | bigint | | plain | |
thread_id | bigint | | plain | |
session_id | bigint | | plain | |
n_soft_parse | bigint | | plain | |
n_hard_parse | bigint | | plain | |
query_plan | text | | extended | |
n_returned_rows | bigint | | plain | |
n_tuples_fetched | bigint | | plain | |
n_tuples_returned | bigint | | plain | |
n_tuples_inserted | bigint | | plain | |
n_tuples_updated | bigint | | plain | |
n_tuples_deleted | bigint | | plain | |
n_blocks_fetched | bigint | | plain | |
n_blocks_hit | bigint | | plain | |
db_time | bigint | | plain | |
cpu_time | bigint | | plain | |
execution_time | bigint | | plain | |
parse_time | bigint | | plain | |
plan_time | bigint | | plain | |
rewrite_time | bigint | | plain | |
pl_execution_time | bigint | | plain | |
pl_compilation_time | bigint | | plain | |
data_io_time | bigint | | plain | |
net_send_info | text | | extended | |
net_recv_info | text | | extended | |
net_stream_send_info | text | | extended | |
net_stream_recv_info | text | | extended | |
lock_count | bigint | | plain | |
lock_time | bigint | | plain | |
lock_wait_count | bigint | | plain | |
lock_wait_time | bigint | | plain | |
lock_max_count | bigint | | plain | |
lwlock_count | bigint | | plain | |
lwlock_wait_count | bigint | | plain | |
lwlock_time | bigint | | plain | |
lwlock_wait_time | bigint | | plain | |
details | bytea | | extended | |
is_slow_sql | boolean | | plain | |
trace_id | text | | extended | |
Indexes:
"statement_history_time_idx" btree (start_time, is_slow_sql) TABLESPACE pg_default
Replica Identity: NOTHING
Has OIDs: no
Options: orientation=row, compression=no

2、性能损耗
track_stmt_stat_level | L0,L2

五月 18, 2022 4:03:1Term-00, Running Average tpmTOTAL: 4663.81 Current tpmTOTAL: 153804 Memory Usage: 20MB / 35MB 16:08:14,743 [Thread-3] INFO jTPCC : Term-00, 16:08:14,744 [Thread-3] INFO jTPCC : Term-00,
16:08:14,744 [Thread-3] INFO jTPCC : Term-00, Measured tpmC (NewOrders) = 2105.31
16:08:14,744 [Thread-3] INFO jTPCC : Term-00, Measured tpmTOTAL = 4663.47
16:08:14,744 [Thread-3] INFO jTPCC : Term-00, Session Start = 2022-05-18 16:03:14
16:08:14,745 [Thread-3] INFO jTPCC : Term-00, Session End = 2022-05-18 16:08:14
16:08:14,745 [Thread-3] INFO jTPCC : Term-00, Transaction Count = 23324

track_stmt_stat_level | off,l2

五月 18, 2022 5:37:0Term-00, Running Average tpmTOTAL: 5475.29 Current tpmTOTAL: 180480 Memory Usage: 17MB / 35MB 17:42:05,837 [Thread-5] INFO jTPCC : Term-00, 17:42:05,837 [Thread-5] INFO jTPCC : Term-00,
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Measured tpmC (NewOrders) = 2476.3
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Measured tpmTOTAL = 5474.86
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Session Start = 2022-05-18 17:37:05
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Session End = 2022-05-18 17:42:05
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Transaction Count = 27381

关掉全量SQL记录后，Running Average tpmTOTAL从4663.81提高到5475.29，tpmTOTAL提升811,性能提升17%。通过测试看到当记录的SQL量很大时，对性能影响较大。建议不要开启FULL SQL，合适设置Slow SQL阀值。

3、保留多久，清理机制
保留时间受参数track_stmt_retention_time控制，经测试，超过设置的保留时间后，旧的记录会陆续被清理。

omm2=# show track_stmt_stat_level;
track_stmt_stat_level
-----------------------
L0,L2
(1 row)

omm2=# show track_stmt_retention_time;
track_stmt_retention_time
---------------------------
3600,604800
(1 row)

select is_slow_sql,count(*),min(start_time),min(finish_time),max(now()) now from statement_history group by is_slow_sql;

is_slow_sql | count | min | min | now
-------------+-------+-------------------------------+-------------------------------+-------------------------------
t | 1 | 2022-05-18 09:54:21.865765+08 | 2022-05-18 09:54:22.871032+08 | 2022-05-18 11:19:23.002656+08
f | 99 | 2022-05-18 10:18:40.599727+08 | 2022-05-18 10:18:40.600507+08 | 2022-05-18 11:19:23.002656+08
(2 rows)

表1 STATEMENT_HISTORY字段

参考
https://docs.mogdb.io/zh/mogdb/v2.1/STATEMENT_HISTORY

名称 类型 描述 记录级别
db_name name 数据库名称。 L0
schema_name name schema名称。 L0
origin_node integer 节点名称。 L0
user_name name 用户名。 L0
application_name text 用户发起的请求的应用程序名称。 L0
client_addr text 用户发起的请求的客户端地址。 L0
client_port integer 用户发起的请求的客户端端口。 L0
unique_query_id bigint 归一化SQL ID。 L0
debug_query_id bigint 唯一SQL ID。 L0
query text 归一化SQL。 L0
start_time timestamp with time zone 语句启动的时间。 L0
finish_time timestamp with time zone 语句结束的时间。 L0
slow_sql_threshold bigint 语句执行时慢SQL的标准。 L0
transaction_id bigint 事务ID。 L0
thread_id bigint 执行线程ID。 L0
session_id bigint 用户session id。 L0
n_soft_parse bigint 软解析次数，n_soft_parse + n_hard_parse可能大于n_calls，因为子查询未计入n_calls。 L0
n_hard_parse bigint 硬解析次数，n_soft_parse + n_hard_parse可能大于n_calls，因为子查询未计入n_calls。 L0
query_plan text 语句执行计划。 L1
n_returned_rows bigint SELECT返回的结果集行数。 L0
n_tuples_fetched bigint 随机扫描行。 L0
n_tuples_returned bigint 顺序扫描行。 L0
n_tuples_inserted bigint 插入行。 L0
n_tuples_updated bigint 更新行。 L0
n_tuples_deleted bigint 删除行。 L0
n_blocks_fetched bigint buffer的块访问次数。 L0
n_blocks_hit bigint buffer的块命中次数。 L0
db_time bigint 有效的DB时间花费，多线程将累加（单位：微秒）。 L0
cpu_time bigint CPU时间（单位：微秒）。 L0
execution_time bigint 执行器内执行时间（单位：微秒）。 L0
parse_time bigint SQL解析时间（单位：微秒）。 L0
plan_time bigint SQL生成计划时间（单位：微秒）。 L0
rewrite_time bigint SQL重写时间（单位：微秒）。 L0
pl_execution_time bigint plpgsql上的执行时间（单位：微秒）。 L0
pl_compilation_time bigint plpgsql上的编译时间（单位：微秒）。 L0
data_io_time bigint IO上的时间花费（单位：微秒）。 L0
net_send_info text 通过物理连接发送消息的网络状态，包含时间（微秒）、调用次数、吞吐量（字节）。通过该字段可以分析SQL在分布式系统下的网络开销，单机模式下不支持该字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 L0
net_recv_info text 通过物理连接接收消息的网络状态，包含时间（微秒）、调用次数、吞吐量（字节）。通过该字段可以分析SQL在分布式系统下的网络开销，单机模式下不支持该字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 L0
net_stream_send_info text 通过逻辑连接发送消息的网络状态，包含时间（微秒）、调用次数、吞吐量（字节）。通过该字段可以分析SQL在分布式系统下的网络开销，单机模式下不支持该字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 L0
net_stream_recv_info text 通过逻辑连接接收消息的网络状态，包含时间（微秒）、调用次数、吞吐量（字节）。通过该字段可以分析SQL在分布式系统下的网络开销，单机模式下不支持该字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 L0
lock_count bigint 加锁次数。 L0
lock_time bigint 加锁耗时。 L1
lock_wait_count bigint 加锁等待次数。 L0
lock_wait_time bigint 加锁等待耗时。 L1
lock_max_count bigint 最大持锁数量。 L0
lwlock_count bigint 轻量级加锁次数（预留）。 L0
lwlock_wait_count bigint 轻量级等锁次数。 L0
lwlock_time bigint 轻量级加锁时间（预留）。 L1
lwlock_wait_time bigint 轻量级等锁时间。 L1
details bytea 语句锁事件的列表，该列表按时间书序记录事件，记录的数量受参数track_stmt_details_size的影响。 L2
事件包括：
- 加锁开始
- 加锁结束
- 等锁开始
- 等锁结束
- 放锁开始
- 放锁结束
- 轻量级等锁开始
- 轻量级等锁结束
is_slow_sql boolean 该SQL是否为slow SQL。 L0
Escape
数据运维
0 0

相关文章

Oracle如何使用授予和撤销权限的语法和示例
Awesome Project: 探索 MatrixOrigin 云原生分布式数据库
下载丨66页PDF，云和恩墨技术通讯（2024年7月刊）
社区版oceanbase安装
Oracle 导出CSV工具-sqluldr2
ETL数据集成丨快速将MySQL数据迁移至Doris数据库

发布评论

Escape

这个人很懒，什么都没有留下～

文章8781 评论0