实现丐版AWR要注意什么?
前言
今天一位朋友找到我说:在函数里面采集pg_stat_activity视图,发现采集的内容不会变化,这样记录的信息就会有误。
分析
首先不妨思考一下为什么需要这么做?其实这个需求还挺常见的,由于PostgreSQL自身不带有原生AWR的功能(需要插件),且pg_stat_activity视图里面也不带有时间戳字段,并且是一个实时类的快照,只能反应某一时刻的状态,因此可行的方案之一就是自己写一个UDF或者其他类似方式,定时采集pg_stat_activity的内容至某张表里,实现一个丐版的"AWR",凑活凑活也能用。
比较典型的案例就是基于pg_stat_statements定时采集实现简易AWR,可以看一下TimescaleDB官方的博客 Point-in-Time PostgreSQL Database and Query Monitoring With pg_stat_statements
举个栗子,我首先复制了pg_stat_activity的结构,然后添加一列额外的时间戳信息用于检索历史数据
[postgres@xiongcc ~]$ psql
psql (14.2)
Type "help" for help.postgres=# create table pg_stat_activity_log as select * from pg_stat_activity limit 0; ---复制表结构
SELECT 0
postgres=# alter table pg_stat_activity_log add column t_time timestamp; ---添加时间列
ALTER TABLE
postgres=# \d pg_stat_activity_log
Table "
public.pg_stat_activity_log"
Column | Type | Collation | Nullable | Default
------------------+-----------------------------+-----------+----------+---------
datid | oid | | |
datname | name | | |
pid | integer | | |
leader_pid | integer | | |
usesysid | oid | | |
usename | name | | |
application_name | text | | |
client_addr | inet | | |
client_hostname | text | | |
client_port | integer | | |
backend_start | timestamp with time zone | | |
xact_start | timestamp with time zone | | |
query_start | timestamp with time zone | | |
state_change | timestamp with time zone | | |
wait_event_type | text | | |
wait_event | text | | |
state | text | | |
backend_xid | xid | | |
backend_xmin | xid | | |
query_id | bigint | | |
query | text | | |
backend_type | text | | |
t_time | timestamp without time zone | | |
接着就是如何采集pg_stat_activity的了,可以参照我这个实现,每隔1s采集一次。
CREATE OR REPLACE FUNCTION public.fn_activity (integer)
RETURNS void
LANGUAGE 'plpgsql'
AS $BODY$
DECLARE
counter integer := 0;
BEGIN
while counter < $1 LOOP
RAISE NOTICE 'Counter %', counter;
counter := counter + 1;
INSERT INTO public.pg_stat_activity_log (datid, datname, pid, leader_pid, usesysid, usename, application_name, client_addr, client_hostname, client_port, backend_start, xact_start, query_start, state_change, wait_event_type, wait_event, state, backend_xid, backend_xmin, query, backend_type, t_time)
SELECT datid, datname, pid, leader_pid, usesysid, usename, application_name, client_addr, client_hostname, client_port, backend_start, xact_start, query_start, state_change, wait_event_type, wait_event, state, backend_xid, backend_xmin, query, backend_type, now()
FROM
pg_stat_activity;
RAISE NOTICE '-------';
PERFORM
pg_sleep(1);
END LOOP;
RETURN;
END;
$BODY$;
下面让我们尝试复现一下,在采集的过程中,新开一个会话使用pgbench模拟一点写流量
postgres=# select fn_activity(30); ---采集30次
NOTICE: Counter 0
NOTICE: -------
NOTICE: Counter 1
NOTICE: -------
NOTICE: Counter 2
NOTICE: -------
NOTICE: Counter 3
NOTICE: -------
NOTICE: Counter 4
NOTICE: -------
NOTICE: Counter 5
NOTICE: -------
NOTICE: Counter 6
...另一边开启会话使用pgbench模拟流量
模拟写入
[postgres@xiongcc ~]$ pgbench -T 60 -c 2 -j 5
pgbench (14.2)
starting vacuum...end.
等采集完成之后,看一下我们的采集结果是否能采集到pgbench的痕迹
postgres=# select pid,query from pg_stat_activity_log where query like '%pgbench%';
pid | query
-----+-------
(0 rows)
果然!我们自己的丐版AWR并未采集到任何关于pgbench的操作,正常来说若我们查询pg_stat_activity视图的话是可以采集到的
postgres=# select pid,query from pg_stat_activity where query like '%pgbench%';
pid | query
-------+------------------------------------------------------------------------
10451 | select pid,query from pg_stat_activity where query like '%pgbench%';
11341 | UPDATE pgbench_branches SET bbalance = bbalance + -4656 WHERE bid = 2;
11342 | UPDATE pgbench_tellers SET tbalance = tbalance + -1768 WHERE tid = 48;
(3 rows)
至此,我们就成功复现出来了问题。
问题在哪
那么问题出在了哪里?为什么会这样?
隔离级别
首先我第一个想到的就是,函数整体是原子性的,可能获取了一个RR以上的快照,因此后续的操作获取不到,那是这样吗?
验证一下,先将采集函数改造一下,额外获取一下快照
CREATE OR REPLACE FUNCTION public.fn_activity (integer)
RETURNS void
LANGUAGE 'plpgsql'
--COST 100
--VOLATILE PARALLEL UNSAFE
AS $BODY$
DECLARE
counter integer := 0;
tmp_snap pg_snapshot; ---用于记录快照
BEGIN
while counter < $1 LOOP
RAISE NOTICE 'Counter %', counter;
counter := counter + 1;
select pg_current_snapshot() into tmp_snap; ---采集当前快照
raise notice 'current snapshot is %',tmp_snap; ---输出当前快照
INSERT INTO public.pg_stat_activity_log (datid, datname, pid, leader_pid, usesysid, usename, application_name,
...
...
END;
$BODY$;
跑一下,可以看到快照进行了更新,但是依旧没有采集到pgbench的操作,说明不是快照搞的鬼。
postgres=# select fn_activity(30);
NOTICE: Counter 0
NOTICE: current snapshot is 318550:318550:
NOTICE: -------
NOTICE: Counter 1
NOTICE: current snapshot is 318550:318550:
NOTICE: -------
NOTICE: Counter 2
NOTICE: current snapshot is 318550:318550:
NOTICE: -------
NOTICE: Counter 3
NOTICE: current snapshot is 318550:318550:
NOTICE: -------
NOTICE: Counter 4
NOTICE: current snapshot is 318550:319170:
NOTICE: -------
NOTICE: Counter 5
NOTICE: current snapshot is 318550:319962:
NOTICE: -------
NOTICE: Counter 6
NOTICE: current snapshot is 318550:320750:
NOTICE: -------
NOTICE: Counter 7
NOTICE: current snapshot is 318550:321494:
NOTICE: -------postgres=# select pid,query from pg_stat_activity_log where query like '%pgbench%';
pid | query
-----+-------
(0 rows)
缓存
另外一个可能的原因会不会是缓存?比如常见的cache plan,因为缓存的原因可能导致走到一个糟糕的执行计划。
我去搜了一下,找到这样一条回答
这里回答就很清晰了
pg_stat_activity和pg_stat_replication两个视图的定义均是基于pg_stat_get_activity()这个函数(可以使用\d+或者pg_get_viewdef证实)。pg_stat_get_activity()这个函数会将每个后端进程的数据缓存下来,这个缓存会在提交/回滚时被清除,但不会像通常那样在 read committed 事务中的每个语句结束时清除。
源码注释里写的很清晰,事务提交或回滚时会调用这个函数进行清理快照。需要使用pg_stat_get_activity()函数手动刷新快照,并且最开始引入的初衷也是为了方便PL/pgSQL。
Add
pg_stat_clear_snapshot()to discard statistics snapshots collected during the current transaction (Tom)The first request for statistics in a transaction takes a statistics snapshot that does not change during the transaction. This function allows the snapshot to be discarded and a new snapshot loaded during the next statistics query. This is particularly useful for PL/pgSQL functions, which are confined to a single transaction.
/* ----------
* pgstat_clear_snapshot() -
*
* Discard any data collected in the current transaction. Any subsequent
* request will cause new snapshots to be read.
*
* This is also invoked during transaction commit or abort to discard
* the no-longer-wanted snapshot.
* ----------
*/
void
pgstat_clear_snapshot(void)
{
/* Release memory, if any was allocated */
if (pgStatLocalContext)
MemoryContextDelete(pgStatLocalContext);
...
试一下RC隔离级别的效果,果然获取不到,事务提交之后才可以。
postgres=# begin;
BEGIN
postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
-------
(0 rows)postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
-------
(0 rows)
postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
-------
(0 rows)
postgres=*# commit ;
COMMIT
postgres=# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
-----------------------------------------------------------
SELECT abalance FROM pgbench_accounts WHERE aid = 478011;
SELECT abalance FROM pgbench_accounts WHERE aid = 552907;
(2 rows)
那再看一下RR呢?这种情况更加获取不到了。
postgres=# begin transaction isolation level repeatable read ;
BEGIN
postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
-------
(0 rows)postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();\watch 1
query
-------
(0 rows)
Wed 25 May 2022 11:14:58 PM CST (every 1s)
query
-------
(0 rows)
Wed 25 May 2022 11:14:59 PM CST (every 1s)
query
-------
(0 rows)
如何解决
方法很简单,调用一下pg_stat_clear_snapshot()函数就行了
postgres=# begin transaction isolation level repeatable read ;
BEGIN
postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();\watch 1
query
-------
(0 rows)Wed 25 May 2022 11:16:11 PM CST (every 1s)
query
-------
(0 rows)
Wed 25 May 2022 11:16:12 PM CST (every 1s)
query
-------
(0 rows)
^Cpostgres=*# select pg_stat_clear_snapshot();
pg_stat_clear_snapshot
------------------------
(1 row)
postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();\watch 1
query
----------------------------------------------------------------------
UPDATE pgbench_tellers SET tbalance = tbalance + 1322 WHERE tid = 8;
UPDATE pgbench_tellers SET tbalance = tbalance + -872 WHERE tid = 4;
(2 rows)
不过值得注意的是,快照并没有发生改变!虽然现象像是刷新了快照,这一点不要搞混了,属实让人有点费解,可以理解为丢弃了缓存。
postgres=# begin transaction isolation level repeatable read ;
BEGIN
postgres=*# select pg_current_snapshot(); ---xmin是525435
pg_current_snapshot
---------------------
525435:525435:
(1 row)postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
-------
(0 rows)
postgres=*# select pg_stat_clear_snapshot();
pg_stat_clear_snapshot
------------------------
(1 row)
postgres=*# select pg_current_snapshot(); ---xmin依旧是525435
pg_current_snapshot
---------------------
525435:525435:
(1 row)
postgres=*# select query from pg_stat_activity where query like '%pgbench%' and pid <> pg_backend_pid();
query
---------------------------------------------------------------------------
UPDATE pgbench_accounts SET abalance = abalance + 185 WHERE aid = 324935;
(1 row)
另外一个有趣的现象是,在官网上有这么一段描述
Another important point is that when a server process is asked to display any of these statistics, it first fetches the most recent report emitted by the collector process and then continues to use this snapshot for all statistical views and functions until the end of its current transaction. So the statistics will show static information as long as you continue the current transaction. Similarly, information about the current queries of all sessions is collected when any such information is first requested within a transaction, and the same information will be displayed throughout the transaction. This is a feature, not a bug, because it allows you to perform several queries on the statistics and correlate the results without worrying that the numbers are changing underneath you. But if you want to see new results with each query, be sure to do the queries outside any transaction block. Alternatively, you can invoke
pg_stat_clear_snapshot(), which will discard the current transaction's statistics snapshot (if any). The next use of statistical information will cause a new snapshot to be fetched.A transaction can also see its own statistics (as yet untransmitted to the collector) in the views
pg_stat_xact_all_tables,pg_stat_xact_sys_tables,pg_stat_xact_user_tables, andpg_stat_xact_user_functions. These numbers do not act as stated above; instead they update continuously throughout the transaction.另一个重要的一点是,当要求服务器进程显示任何这些统计信息时,它首先获取收集器进程发出的最新报告,然后继续使用此快照来查看所有统计视图和函数,直到其当前事务结束.因此,只要您继续当前事务,统计信息就会显示静态信息。同样,当在事务中首次请求任何此类信息时,将收集有关所有会话的当前查询的信息,并且将在整个事务中显示相同的信息。这是一项特性,而不是BUG,因为它允许您对统计信息执行多个查询并关联结果,而不必担心您下面的数字会发生变化。但是,如果您想查看每个查询的新结果,请务必在任何事务块之外进行查询。或者,您可以调用 pg_stat_clear_snapshot(),这将丢弃当前事务的统计快照(如果有)。下次使用统计信息将导致获取新的快照。
事务还可以在视图 pg_stat_xact_all_tables、pg_stat_xact_sys_tables、pg_stat_xact_user_tables 和 pg_stat_xact_user_functions 中查看其自己的统计信息(尚未传输到收集器)。这些数字与上述不同;相反,它们在整个事务过程中不断更新。
pg_stat_xact_user_tables这些视图是类似于Oracle的实时动态性能视图,用于采集当前事务的活动。
Similar to
pg_stat_all_tables, but counts actions taken so far within the current transaction (which are not yet included inpg_stat_all_tablesand related views). The columns for numbers of live and dead rows and vacuum and analyze actions are not present in this view.
让我们验证一下,正如官网所说
pg_stat_xact_all_tables反应的是当前事务内的操作,会实时变化 pg_stat_all_tables这类视图只有视图提交了才能看到变化
postgres=# create table t(id int);
CREATE TABLE
postgres=# begin;
BEGIN
postgres=*# insert into t values(1);
INSERT 0 1
postgres=*# insert into t values(2);
INSERT 0 1
postgres=*# select n_tup_ins from pg_stat_xact_user_tables where relid = 't'::regclass; ---pg_stat_xact_user_tables实时更新
n_tup_ins
-----------
2
(1 row)postgres=*# select n_tup_ins,n_live_tup from pg_stat_all_tables where relid = 't'::regclass;
n_tup_ins | n_live_tup
-----------+------------
0 | 0
(1 row)
postgres=*# select pg_stat_clear_snapshot();
pg_stat_clear_snapshot
------------------------
(1 row)
postgres=*# select n_tup_ins,n_live_tup from pg_stat_all_tables where relid = 't'::regclass;
n_tup_ins | n_live_tup
-----------+------------
0 | 0
(1 row)
postgres=*# commit ;
COMMIT
postgres=# select n_tup_ins,n_live_tup from pg_stat_all_tables where relid = 't'::regclass; ---pg_stat_all_tables只有事务提交才更新
n_tup_ins | n_live_tup
-----------+------------
2 | 2
(1 row)
注意什么
现在我们来写个UDF采集一下pg_stat_all_tables,看看会不会发生变化(存储过程procedure也是一样的效果,可自行验证)
CREATE OR REPLACE FUNCTION public.fn_all_tables (integer)
RETURNS void
LANGUAGE 'plpgsql'
--COST 100
--VOLATILE PARALLEL UNSAFE
AS $BODY$
DECLARE
counter integer := 0;
tmp_snap pg_snapshot;
BEGIN
while counter < $1 LOOP
RAISE NOTICE 'Counter %', counter;
counter := counter + 1;
select pg_current_snapshot() into tmp_snap;
raise notice 'current snapshot is %',tmp_snap;
INSERT INTO public.pg_stat_all_tables_log(relname,n_tup_ins) select relname,n_tup_ins
FROM
pg_stat_all_tables where relname = 't';
RAISE NOTICE '-------';
PERFORM
pg_sleep(1);
END LOOP;
RETURN;
END;
$BODY$;
postgres=# drop table t;
DROP TABLE
postgres=# create table t(id int);
CREATE TABLE
postgres=# insert into t values(1);\watch
INSERT 0 1
可以看到采集的数据始终是不变的,但是函数内的快照是会变的
postgres=# select fn_all_tables(10);
NOTICE: Counter 0
NOTICE: current snapshot is 564928:564928:
NOTICE: -------
NOTICE: Counter 1
NOTICE: current snapshot is 564928:564928:
NOTICE: -------
NOTICE: Counter 2
NOTICE: current snapshot is 564928:564930:
NOTICE: -------
NOTICE: Counter 3
NOTICE: current snapshot is 564928:564930:
NOTICE: -------
NOTICE: Counter 4
NOTICE: current snapshot is 564928:564931:
NOTICE: -------
NOTICE: Counter 5
NOTICE: current snapshot is 564928:564931:
NOTICE: -------
NOTICE: Counter 6
NOTICE: current snapshot is 564928:564932:
NOTICE: -------
NOTICE: Counter 7
NOTICE: current snapshot is 564928:564932:
NOTICE: -------
NOTICE: Counter 8
NOTICE: current snapshot is 564928:564933:
NOTICE: -------
NOTICE: Counter 9
NOTICE: current snapshot is 564928:564933:
NOTICE: -------
fn_all_tables
--------------- (1 row)
postgres=# select * from pg_stat_all_tables_log ;
relname | n_tup_ins
---------+-----------
t | 4
t | 4
t | 4
t | 4
t | 4
t | 4
t | 4
t | 4
t | 4
t | 4
(10 rows)
因此需要改造一下,每次手动刷新一下快照
CREATE OR REPLACE FUNCTION public.fn_all_tables (integer)
RETURNS void
LANGUAGE 'plpgsql'
--COST 100
--VOLATILE PARALLEL UNSAFE
AS $BODY$
DECLARE
counter integer := 0;
tmp_snap pg_snapshot;
BEGIN
while counter < $1 LOOP
RAISE NOTICE 'Counter %', counter;
counter := counter + 1;
select pg_current_snapshot() into tmp_snap;
raise notice 'current snapshot is %',tmp_snap;
INSERT INTO public.pg_stat_all_tables_log(relname,n_tup_ins) select relname,n_tup_ins
FROM
pg_stat_all_tables where relname = 't';
RAISE NOTICE '-------';
PERFORM
pg_sleep(1);
PERFORM
pg_stat_clear_snapshot(); ---每次循环都刷新一次快照
END LOOP;
RETURN;
END;
$BODY$;
这样就可以获取到最新的数据了
postgres=# select * from pg_stat_all_tables_log ;
relname | n_tup_ins
---------+-----------
t | 1
t | 3
t | 3
t | 4
t | 4
t | 5
t | 6
t | 6
t | 7
t | 7
(10 rows)
小结
使用到pg_stat_get_activity()函数的总共有四个系统视图,/src/backend/catalog/system_views.sql,分别是
pg_stat_activity pg_stat_replication pg_stat_ssl pg_stat_gssapi
另外在函数或存储过程里采集性能和活动视图的时候都有这个问题,因此假如我们要使用UDF来实现性能采集,都需要在函数体内加上pg_stat_clear_snapshot(),否则获取的数据不会发生改变,官方称之为feature 🤫🤫
可以改一下我的例子,都可以证实采集的结果是不会变的。
CREATE OR REPLACE FUNCTION public.collect_perfomance (int)
RETURNS SETOF pg_stat_database
LANGUAGE 'plpgsql'
--COST 100
--VOLATILE PARALLEL UNSAFE
AS $BODY$
DECLARE
var record;
counter integer := 0;
tmp_snap pg_snapshot;
BEGIN
while counter < $1 LOOP
RAISE NOTICE 'Counter %', counter;
counter := counter + 1;
SELECT
pg_current_snapshot () INTO tmp_snap;
RAISE NOTICE 'current snapshot is %', tmp_snap;
FOR var IN EXECUTE format($$select * from pg_stat_database where datname = 'postgres'$$)
LOOP
RETURN NEXT var;
END LOOP;
PERFORM
pg_sleep(1);
END LOOP;
RETURN;
END;
$BODY$;postgres=# select collect_perfomance(10);
NOTICE: Counter 0
NOTICE: current snapshot is 821963:821963:
NOTICE: Counter 1
NOTICE: current snapshot is 822747:822747:
NOTICE: Counter 2
NOTICE: current snapshot is 823513:823513:
NOTICE: Counter 3
NOTICE: current snapshot is 824270:824270:
NOTICE: Counter 4
NOTICE: current snapshot is 825023:825023:
NOTICE: Counter 5
NOTICE: current snapshot is 825763:825763:
NOTICE: Counter 6
NOTICE: current snapshot is 826499:826499:
NOTICE: Counter 7
NOTICE: current snapshot is 827225:827225:
NOTICE: Counter 8
NOTICE: current snapshot is 827944:827944:
NOTICE: Counter 9
NOTICE: current snapshot is 828654:828654:
collect_perfomance
----------------------------------------------------------------------------------------------------------------------------------------------------------------
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(16415,postgres,3,12931,21,12376,276867,90934,54434,12913,38588,57,0,0,0,0,,,776.12,0,1415648.935,20939.269,20549.313,4,0,0,1,"2022-05-26 14:08:37.419556+08")
(10 rows)
不过有趣的是,openGuass可以事务内动态采集,有空了去看一下openGuass做了什么改动。
参考
https://www.postgresql.org/docs/current/monitoring-stats.html
https://stackoverflow.com/questions/41421429/pg-stat-activity-doesnt-update-within-a-procedure-or-transaction