一、概述
二、ASP
01
特性简介
-
最近用户session最耗资源的的事件 -
最近比较占资源的session/SQL把资源都消耗在哪些event上 -
最近执行时间/执行次数最多的是哪些SQL(进而可以找出表，数据库) -
最近最耗资源的用户的信息 -
最近阻塞其他session最多的session
02
工作机制
step1：周期采集信息
MogDB 启动后会启动一个后台worker采样线程，为避免浪费资源，该采样线程不会时刻采样，而是每隔一个采样周期对 MogDB 进行采样，收集 MogDB 当时的运行快照保存到内存中，查询视图dbe_perf.local_active_session可以查询到实时的采样信息，该采样周期由guc参数asp_sample_interval控制，默认采样周期为1s。 只有语句执行时间大于采样时间(1s)，才会被采样线程收集到运行信息。
step2：信息持久化
MogDB 每在内存中采样100000行（由guc参数 asp_sample_num 控制）会将内存中的采样数据刷新到GS_ASP表中以供历史查询。
03
相关视图
1. dbe_perf.local_active_session
2. pg_catalog.gs_asp
GS_ASP 显示被持久化的ACTIVE SESSION PROFILE样本，该表只在系统库(postgres)下查询，在用户库下查询无数据。
04
相关重要参数
1. enable_asp
参数说明： 是否开启活跃会话信息active session profile。 重新加载参数后，立即生效。
可选项：
-
enable_asp=on --开启
-
enable_asp=off --关闭
2. asp_sample_interval
参数说明：信息采样的间隔。重新加载参数后，立即生效。
-
asp_sample_interval=1s --默认1s
3. asp_sample_num
参数说明：LOCAL_ACTIVE_SESSION视图最大的样本个（行）数，超过该数值，数据会刷新到GS_ASP表。数据库重启后生效。
-
asp_sample_interval=100000 --默认100000
参数说明：指定每多少个内存asp sample条目转存到磁盘上。在一些特定的场景下，比如有些定期任务总是在整点运行，可能导致一直采集不到，可以考虑把这个值设为7或者11，这样，可以让采样更为多样化。
三、Full SQL TRACE & Slow SQL
01
特性简介
-
MogDB 会记录全量SQL信息，分为L0, L1,L2三个等级，可以获取以下信息：
-
可以获取实例信息，客户端信息，语句概要信息，执行信息，行活动信息，Cache/IO，时间模型，网络统计信息，锁概要信息，锁详细信息等。 -
通过全量SQL，可以得到整个系统所有语句的执行流水以 及他们的详细性能数据(持久化的)。 -
除Statement视图提供的能力外，还额外提供了详细加放锁信息，可以诊断到单语句级别的性能波动。
-
达到慢查询阈值( log_min_duration_statement )设置的语句性能信息，性能要素和全量SQL一致。
02
相关视图
1. dbe_perf.statement
需要打开enable_resource_track参数：允许运行时候的资源使用追踪。
2. dbe_perf.statement_complex_runtime
视图显示当前用户在数据库主节点上正在执行的作业的负载管理记录。
我们可以利用此试图来查看当前执行sql的执行计划、语句执行状态等详细信息来排查sql性能问题。
3. dbe_perf.statement_history
我们可以利用此视图来查询历史sql的的详细运行信息。此视图受log_duration、log_min_duration_statement、track_stmt_stat_level等参数控制。并且需要判断：
以下各个条件为或判定，满足其一即可：
-
打开了动态语句追踪功能：采用dynamic_func_control追踪STMT。
-
track_stmt_stat_level追踪第一个level为L0或者更高。
-
track_stmt_stat_level追踪第二个level为L0或者更高，且语句运行时间大于log_min_duration_statement设定值，且log_min_duration_statement大于等于0，并且没有打开track_stmt_parameter。
-
打开track_stmt_parameter，并且时间模式第一个值（消耗的DBTIME）大于0。
03
相关重要参数
1. enable_resource_track
参数说明：是否开启资源实时监控功能。重新加载参数后，立即生效。
可选项：
-
enable_resource_track=on --开启
-
enable_resource_track=off --关闭
2. track_stmt_stat_level
参数说明：控制语句执行跟踪的级别。该参数分为两部分，形式为’full sql stat level, slow sql stat level’；
full sql stat level为全量SQL跟踪级别，取值范围为OFF、L0、L1、L2
slow sql stat level为慢SQL的跟踪级别，取值范围为OFF、L0、L1、L2
—若全量SQL跟踪级别值为非OFF时，当前SQL跟踪级别值为全量SQL和慢SQL的较高·级别（L2 > L1 > L0）
—L1在L0的基础上记录了执行计划，L2在L1的基础上记录了锁的详细信息，详情见statement_history中的details
-
track_stmt_stat_level=OFF,L0 --默认配置，表示关闭全量sql跟踪，开启L0级别的慢SQL跟踪
-
track_stmt_stat_level=L2,L0 --表示此时SQL跟踪级别都为L2
3. resource_track_cost
参数说明：设置对当前会话的语句进行资源监控的最小执行代价。该参数只有当参数enable_resource_track为on时才有效。
可选项：
-
resource_track_cost=-1 --不进行资源监控。
-
resource_track_cost=0 --【0-9】对执行代价大于等于10的语句进行资源监控。
-
resource_track_cost=10 --【>10】,对执行代价超过该参数值的语句进行资源监控。
4. resource_track_level
none：不开启资源记录功能；
query：开启query级别资源记录功能；
operator：开启query级别和算子级别资源记录功能，
如果需要监控执行计划中每个算子操作，需要将resource_track_level设成operator。
5. log_min_duration_statement
参数说明：当某条语句的持续时间大于或者等于特定的毫秒数时，log_min_duration_statement参数用于控制记录每条完成语句的持续时间。
可选项：
-
log_min_duration_statement=1000ms --所有运行时间不短于1000ms的SQL语句都会被记录。
-
log_min_duration_statement=0 --所有语句都会被记录
-
log_min_duration_statement=-1 --关闭此功能
6. log_duration
参数说明：控制记录每个已完成SQL语句的执行时间。对使用扩展查询协议的客户端、会记录语法分析、绑定和执行每一步所花费的时间。
可选项：
-
log_duration=on --默认，开启
-
log_duration=off --关闭
四、确认参数
enable_asp = on
--开启ASP采样
enable_resource_track = on
--开启资源实时监控
log_duration = on
--开启【记录sql执行时间】功能
log_min_duration_statement = 1000
--1000ms，即1s，执行时长超过该参数，会记录为慢SQL
track_stmt_stat_level = 'L2,L0'
--资源追踪级别为L2
resource_track_cost = 10
--当前会话的语句执行cost需要大于该参数值，才会被记录到相关视图
#其他相关参数可保持默认
五、测试
01
查看当前执行计划
1. 官方示例
详细信息可参考官方文档：SQL运行状态观测 (h ttps://docs.mogdb.io/zh/mogdb/v3.0/22-sql-running-status-observation#) 。
-
session 1 创建测试表并插入数据
MogDB=# create table test1(id int);
CREATE TABLE
MogDB=# insert into test1 select generate_series(1, 10000000);
-
session 2 通过pg_stat_activity查询到query_id
通过活跃会话视图查询到正在执行sql的query_id（执行完毕的sql是不会记录在该视图）
MogDB=# select query,query_id from pg_stat_activity where query like 'insert into test1 select%';
query | query_id
--------------------------------------------------------+------------------
insert into test1 select generate_series(1, 10000000); | 3940649673950800
(1 row)
-
session 2 查看当前SQL执行计划
根据该query_id从活跃作业管理视图中查询出该语句的带plan_node_id(执行计划树的算子id)的执行计划（该语句执行cost需要大于guc值resource_track_cost才会被记录到该视图中，该guc参数默认值为100000，session级别可更新，所以为了方便测试，可在测试中将该值改成10）。
MogDB=# select query_plan from dbe_perf.statement_complex_runtime where queryid =3940649673950800 ;
query_plan
-----------------------------------------------------------
Coordinator Name: dn_6001 +
1 | Insert on test1 (cost=0.00..15.01 rows=1000 width=4)+
2 | -> Result (cost=0.00..5.01 rows=1000 width=0) +
+
-
s ession 2 查询算子采样详情
MogDB=# select plan_node_id, count(plan_node_id) from dbe_perf.local_active_session where query_id =3940649673950800 group by plan_node_id;
plan_node_id | count
--------------+-------
1 | 39
2 | 1
-
有可能上一步查询没有结果，很有可能内存数据到达了上限值（由guc参数asp_sample_num控制），此时需要查询gs_asp表。
select plan_node_id, count(plan_node_id) from dbe_perf.local_active_session where query_id =3940649673950800 group by plan_node_id;
-
结论
2. 实际应用
-
session 1 统计test1和test2中相同数据的个数
MogDB=# select count(*)
MogDB-# from test1 t1,test2 t2
MogDB-# where t1.id = t2.id;
-
session 2 查询执行计划及算子采样详情
MogDB=# select query,query_id,unique_sql_id from pg_stat_activity where query like 'select count(*)%';
query | query_id | unique_sql_id
------------------------+------------------+---------------
select count(*) +| 3940649673951393 | 4071767743
from test1 t1,test2 t2+| |
where t1.id = t2.id; | |
MogDB=# select query_plan,query,duration from dbe_perf.statement_complex_runtime where queryid = 3940649673951393;
query_plan | query | duration
-------------------------------------------------------------------------------+------------------------+----------
Coordinator Name: dn_6001 +| select count(*) +| 65740
1 | Aggregate (cost=955172.77..955172.78 rows=1 width=8) +| from test1 t1,test2 t2+|
2 | -> Hash Join (cost=357141.08..928597.94 rows=10629931 width=0) +| where t1.id = t2.id; |
| Hash Cond: (t2.id = t1.id) +| |
3 | -> Seq Scan on test2 t2 (cost=0.00..150547.31 rows=10629931 width=4) +| |
4 | -> Hash (cost=144248.48..144248.48 rows=10000048 width=4) +| |
5 | -> Seq Scan on test1 t1 (cost=0.00..144248.48 rows=10000048 width=4)+| |
+| |
| |
MogDB=# select plan_node_id, count(plan_node_id) from dbe_perf.local_active_session where query_id =3940649673951393 group by plan_node_id;
plan_node_id | count
--------------+-------
5 | 44
3 | 55
2 | 6
-
结论：
对两个表的id字段都创建索引：
create index test_index1 on test1(id);
create index test_index2 on test2(id);
对比一下创建索引与创建索引之前的SQL执行用时,还是有很大的差距。
MogDB=# select query_plan,query,is_slow_sql,start_time,finish_time
from dbe_perf.statement_history sh
where sh.query like 'select count(*)%' ;
-[ RECORD 1 ]------------------------------------------------------------------------------------------------------------------------------------------------------------
query_plan | Datanode Name: dn_6001
| Aggregate (cost=783458.91..783458.92 rows=1 width=8) (actual time=12565.353..12565.354 rows=1 loops=1)
| -> Merge Join (cost=11.79..758458.91 rows=10000000 width=0) (actual time=0.259..11674.363 rows=10000000 loops=1)
| Merge Cond: (t1.id = t2.id)
| -> Index Only Scan using test_index1 on test1 t1 (cost=0.00..304239.25 rows=10000000 width=4) (actual time=0.116..3775.731 rows=10000000 loops=1)
| -> Index Only Scan using test_index2 on test2 t2 (cost=0.00..304239.25 rows=10000000 width=4) (actual time=0.082..4418.354 rows=10000000 loops=1)
|
|
query | select count(*)
| from test1 t1,test2 t2
| where t1.id = t2.id;
is_slow_sql | t
start_time | 2022-09-10 20:03:39.300469+08
finish_time | 2022-09-10 20:03:51.893721+08
-[ RECORD 2 ]------------------------------------------------------------------------------------------------------------------------------------------------------------
query_plan | Datanode Name: dn_6001
| Aggregate (cost=955172.77..955172.78 rows=1 width=8) (actual time=109007.337..109007.338 rows=1 loops=1)
| -> Hash Join (cost=357141.08..928597.94 rows=10629931 width=0) (actual time=45339.277..108223.237 rows=10000000 loops=1)
| Hash Cond: (t2.id = t1.id)
| -> Seq Scan on test2 t2 (cost=0.00..150547.31 rows=10629931 width=4) (actual time=0.128..54984.720 rows=10000000 loops=1)
| -> Hash (cost=144248.48..144248.48 rows=10000048 width=4) (actual time=45278.900..45278.900 rows=10000000 loops=1)
| Buckets: 2097152 Batches: 16 Memory Usage: 21976kB
| -> Seq Scan on test1 t1 (cost=0.00..144248.48 rows=10000048 width=4) (actual time=1.324..43240.923 rows=10000000 loops=1)
|
|
query | select count(*)
| from test1 t1,test2 t2
| where t1.id = t2.id;
is_slow_sql | t
start_time | 2022-09-10 18:24:45.876048+08
finish_time | 2022-09-10 18:26:34.899024+08
02
查看历史SQL执行计划
对于执行中的SQL我们可以利用statement_complex_runtime视图获取当前语句的执行计划，以便我们进行分析。 但是这个视图只是针对正在执行的作业的负载管理记录。 而对于执行完成后的sql，我们想获取执行计划，进行分析就需要借助dbe_perf.statement_history这个视图。
1. 实际应用
MogDB=# select count(*)
MogDB-# from test1 t1,test2 t2
MogDB-# where t1.id = t2.id;
-[ RECORD 1 ]---
count | 10000000
-
根据unique_sql_id/query_id获取执行计划
上节中我们查询了当时正在执行sql的unique_sql_id，它对应statement_history中的unique_query_id。query_id对应此视图的debug_query_id
MogDB=# \x
Expanded display is on.
MogDB=# select query_plan,sh.*
MogDB-# from dbe_perf.statement_history sh
MogDB-# where sh.unique_query_id='4071767743';
-[ RECORD 1 ]--------+--------------------------------------------------------------------------------------------
query_plan | Datanode Name: dn_6001
| Aggregate (cost=955172.77..955172.78 rows=1 width=8) (actual time=109007.337..109007.338 rows=1 loops=1)
| -> Hash Join (cost=357141.08..928597.94 rows=10629931 width=0) (actual time=45339.277..108223.237 rows=10000000 loops=1)
| Hash Cond: (t2.id = t1.id)
| -> Seq Scan on test2 t2 (cost=0.00..150547.31 rows=10629931 width=4) (actual time=0.128..54984.720 rows=10000000 loops=1)
| -> Hash (cost=144248.48..144248.48 rows=10000048 width=4) (actual time=45278.900..45278.900 rows=10000000 loops=1)
| Buckets: 2097152 Batches: 16 Memory Usage: 21976kB
| -> Seq Scan on test1 t1 (cost=0.00..144248.48 rows=10000048 width=4) (actual time=1.324..43240.923 rows=10000000 loops=1)
|
|
db_name | postgres
schema_name | "$user",public
origin_node | 0
user_name | omm
application_name | gsql
client_addr |
client_port | -1
unique_query_id | 4071767743
debug_query_id | 3940649673951393
query | select count(*)
| from test1 t1,test2 t2
| where t1.id = t2.id;
start_time | 2022-09-10 18:24:45.876048+08
finish_time | 2022-09-10 18:26:34.899024+08
slow_sql_threshold | 1000000
transaction_id | 0
thread_id | 70371368087664
session_id | 70371368087664
n_soft_parse | 0
n_hard_parse | 1
query_plan | Datanode Name: dn_6001
| Aggregate (cost=955172.77..955172.78 rows=1 width=8) (actual time=109007.337..109007.338 rows=1 loops=1)
| -> Hash Join (cost=357141.08..928597.94 rows=10629931 width=0) (actual time=45339.277..108223.237 rows=10000000 loops=1)
| Hash Cond: (t2.id = t1.id)
| -> Seq Scan on test2 t2 (cost=0.00..150547.31 rows=10629931 width=4) (actual time=0.128..54984.720 rows=10000000 loops=1)
| -> Hash (cost=144248.48..144248.48 rows=10000048 width=4) (actual time=45278.900..45278.900 rows=10000000 loops=1)
| Buckets: 2097152 Batches: 16 Memory Usage: 21976kB
| -> Seq Scan on test1 t1 (cost=0.00..144248.48 rows=10000048 width=4) (actual time=1.324..43240.923 rows=10000000 loops=1)
|
|
n_returned_rows | 1
n_tuples_fetched | 12
n_tuples_returned | 20000006
n_tuples_inserted | 0
n_tuples_updated | 0
n_tuples_deleted | 0
n_blocks_fetched | 88524
n_blocks_hit | 26
db_time | 109023716
cpu_time | 87062876
execution_time | 109008897
parse_time | 537
plan_time | 3121
rewrite_time | 34
pl_execution_time | 0
pl_compilation_time | 0
data_io_time | 2073831
net_send_info | {"time":42193, "n_calls":932, "size":74606}
net_recv_info | {"time":262575283, "n_calls":1, "size":65}
net_stream_send_info | {"time":0, "n_calls":0, "size":0}
net_stream_recv_info | {"time":0, "n_calls":0, "size":0}
lock_count | 42
lock_time | 204
lock_wait_count | 0
lock_wait_time | 0
lock_max_count | 6
lwlock_count | 0
lwlock_wait_count | 0
lwlock_time | 0
lwlock_wait_time | 0
details | \x120c0000010001a91419d74e8b020000000000ec0400000000000000000000000000010100000002201519d74e8b0200056c1619d74e8b020000000000ec04000000000000000000000.........
is_slow_sql | t
trace_id |
-
根据其他字段信息获取执行计划
如果不清楚有关该SQL的query_id等信息，也可以利用其他知晓的字段信息，如sql语句（query）、开始执行时间（start_time）等信息进行查询。下方为示例
MogDB=# select query_plan
MogDB-# from dbe_perf.statement_history sh
MogDB-# where sh.query like 'select count(*)%' and start_time='2022-09-10 18:24:45.876048+08';
-[ RECORD 1 ]-----------------------------------------------------------------------------------------------------------------------------------------
query_plan | Datanode Name: dn_6001
| Aggregate (cost=955172.77..955172.78 rows=1 width=8) (actual time=109007.337..109007.338 rows=1 loops=1)
| -> Hash Join (cost=357141.08..928597.94 rows=10629931 width=0) (actual time=45339.277..108223.237 rows=10000000 loops=1)
| Hash Cond: (t2.id = t1.id)
| -> Seq Scan on test2 t2 (cost=0.00..150547.31 rows=10629931 width=4) (actual time=0.128..54984.720 rows=10000000 loops=1)
| -> Hash (cost=144248.48..144248.48 rows=10000048 width=4) (actual time=45278.900..45278.900 rows=10000000 loops=1)
| Buckets: 2097152 Batches: 16 Memory Usage: 21976kB
| -> Seq Scan on test1 t1 (cost=0.00..144248.48 rows=10000048 width=4) (actual time=1.324..43240.923 rows=10000000 loops=1)
|
|
2. 慢SQL诊断
MogDB=# select * from dbe_perf.get_global_full_sql_by_timestamp('2022-09-10 18:24:45','2022-09-10 18:26:45') ;
-[ RECORD 1 ]--------+--------------------------------------------------------------------------------------------
node_name | dn_6001
db_name | postgres
schema_name | "$user",public
origin_node | 0
user_name | omm
application_name | gsql
client_addr |
client_port | -1
unique_query_id | 4071767743
debug_query_id | 3940649673951393
query | select count(*)
| from test1 t1,test2 t2
| where t1.id = t2.id;
start_time | 2022-09-10 18:24:45.876048+08
finish_time | 2022-09-10 18:26:34.899024+08
slow_sql_threshold | 1000000
transaction_id | 0
thread_id | 70371368087664
session_id | 70371368087664
n_soft_parse | 0
n_hard_parse | 1
query_plan | Datanode Name: dn_6001
| Aggregate (cost=955172.77..955172.78 rows=1 width=8) (actual time=109007.337..109007.338 rows=1 loops=1)
| -> Hash Join (cost=357141.08..928597.94 rows=10629931 width=0) (actual time=45339.277..108223.237 rows=10000000 loops=1)
| Hash Cond: (t2.id = t1.id)
| -> Seq Scan on test2 t2 (cost=0.00..150547.31 rows=10629931 width=4) (actual time=0.128..54984.720 rows=10000000 loops=1)
| -> Hash (cost=144248.48..144248.48 rows=10000048 width=4) (actual time=45278.900..45278.900 rows=10000000 loops=1)
| Buckets: 2097152 Batches: 16 Memory Usage: 21976kB
| -> Seq Scan on test1 t1 (cost=0.00..144248.48 rows=10000048 width=4) (actual time=1.324..43240.923 rows=10000000 loops=1)
|
|
n_returned_rows | 1
n_tuples_fetched | 12
n_tuples_returned | 20000006
n_tuples_inserted | 0
n_tuples_updated | 0
n_tuples_deleted | 0
n_blocks_fetched | 88524
n_blocks_hit | 26
db_time | 109023716
cpu_time | 87062876
execution_time | 109008897
parse_time | 537
plan_time | 3121
rewrite_time | 34
pl_execution_time | 0
pl_compilation_time | 0
data_io_time | 2073831
net_send_info | {"time":42193, "n_calls":932, "size":74606}
net_recv_info | {"time":262575283, "n_calls":1, "size":65}
net_stream_send_info | {"time":0, "n_calls":0, "size":0}
net_stream_recv_info | {"time":0, "n_calls":0, "size":0}
lock_count | 42
lock_time | 204
lock_wait_count | 0
lock_wait_time | 0
lock_max_count | 6
lwlock_count | 0
lwlock_wait_count | 0
lwlock_time | 0
lwlock_wait_time | 0
details | \x120c0000010001a91419d74e8b020000000000ec0400000000000000000000000000010100000002201519d74e8b0200056c1619d74e8b020000000000ec04000000000000000000000.......
is_slow_sql | t
trace_id |
六、总结
综上，我们可以灵活地使用多个视图去查看SQL的执行计划以及其他相关信息，以下总结了本文使用的查询语句：
01
查询当前正在执行SQL的执行计划
-
定位SQL以及对应的query_id
select query,query_id,unique_sql_id
from pg_stat_activity
where query like 'select count(*)%';
-
获取目标SQL的执行计划
select query_plan,query
from dbe_perf.statement_complex_runtime
where query_id = $query_id;
02
查询历史SQL执行计划
-
通过query_id,unique_query_id获取执行计划
pg_stat_activity中的query_id对应statement_history的debug_query_id;
pg_stat_activity中的unique_sql_id对应statement_history的unique_query_id;
select query_plan,sh.*
from dbe_perf.statement_history sh
where sh.unique_query_id=$unique_sql_id;
-
通过其他已知条件获取执行计划
select query,query_plan
from dbe_perf.statement_history sh
where sh.query like 'xxxxx' and sh.start_time='xxxx';
03
分析算子采样信息
-
通过local_active_session/gs_asp视图来获取算子采样信息
select plan_node_id, count(plan_node_id)
from dbe_perf.local_active_session
where query_id =$query_ID
group by plan_node_id;
计数越大的plan_node_id，对应的算子执行时间越长。
04
通过其他函数获取SQL信息
-
可以通过get_global_full_sql_by_timestamp()类函数来获取某一时间段内所有SQL的信息，包括执行计划
select * from dbe_perf.get_global_full_sql_by_timestamp('2022-09-10 18:24:45','2022-09-10 18:26:45') ;
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/29715045/viewspace-3024642/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- 通用数据库一体机zData X：性能、成本、运维全面优化，带来多元数据库承载体验提升
- 精进不休丨MogDB 数据库预读特性进一步提升20%+查询性能
- 精进不休丨存储过程代码超过百万行的 Oracle 数据库迁移，MogDB 这样就搞定了？
- MogDB 插件式机制在实现多数据库方言框架兼容与平滑迁移中的价值
- 云和恩墨与华为共同发布数据库存算分离+双集群容灾架构联合解决方案
- 循序渐进丨不小心搞坏了一个生产表，MogDB还能救吗？
- 精进不休丨如何成为兼容 MySQL 程度最高的国产数据库之一？
- 循序渐进丨Oracle 通过透明网关以dblink形式连接 MogDB 的方法
- 循序渐进丨MogDB 数据库分区表的静态数据分区删除测试
- 不得了！这个国产数据库居然实现了Oracle的聚合函数wm_concat
