PostgreSQL Systemtap example : autovacuum_naptime & databases in cluster

2 minute read

背景

本文是一个systemtap的使用例子, 从这里例子观察到的一个现象.  
autovacuum_naptime 这个参数和数据库个数的关系, 以及如何影响autovacuum进程唤醒频率的.  
数据库进程如下 :   
[root@db-172-16-3-39 ~]# ps -ewf|grep postgres  
pg93     28144     1  0 10:39 pts/3    00:00:00 /home/pg93/pgsql9.3.0/bin/postgres  
pg93     28145 28144  0 10:39 ?        00:00:00 postgres: logger process            
pg93     28147 28144  0 10:39 ?        00:00:00 postgres: checkpointer process      
pg93     28148 28144  0 10:39 ?        00:00:00 postgres: writer process            
pg93     28149 28144  0 10:39 ?        00:00:00 postgres: wal writer process        
pg93     28150 28144  0 10:39 ?        00:00:00 postgres: autovacuum launcher process     
pg93     28151 28144  0 10:39 ?        00:00:00 postgres: archiver process          
pg93     28152 28144  0 10:39 ?        00:00:00 postgres: stats collector process  
数据库没有任何连接.  
stap脚本如下, 运行一段时间后发现没有连接居然会有transaction__start探针被触发了.  
[root@db-172-16-3-39 utils]# stap -e 'probe process("/home/pg93/pgsql9.3.0/bin/postgres").mark("transaction__start") {printdln("arg1,execname(),pid(),tid(),cpu(),gettimeofday_s(),thread_indent(1)); }'  
535/postgres/28150/28150/1/1381388788/     0 postgres(28150):  
1014/postgres/2179/2179/1/1381388788/     0 postgres(2179):  
1015/postgres/2179/2179/1/1381388788/ 10786 postgres(2179):   
536/postgres/28150/28150/1/1381388818/30322989 postgres(28150):   
1016/postgres/2188/2188/1/1381388818/     0 postgres(2188):  
1017/postgres/2188/2188/1/1381388818/ 10867 postgres(2188):   
537/postgres/28150/28150/1/1381388848/60098973 postgres(28150):    
1018/postgres/2190/2190/1/1381388848/     0 postgres(2190):  
1019/postgres/2190/2190/1/1381388848/ 10925 postgres(2190):   
538/postgres/28150/28150/1/1381388878/90421976 postgres(28150):     
1020/postgres/2192/2192/1/1381388878/     0 postgres(2192):  
1021/postgres/2192/2192/1/1381388878/ 10981 postgres(2192):   
以上进程号28150对应postgresql的autovacuum launcher process进程.  
从结果上发现有一定的规律性, 每隔30秒会输出一次.  
每隔一段时间autovacuum launcher process进程会告知postgresql主进程fork autovacuum worker进程进行vacuum操作 .  
使用以下的syscall.fork探针能看到这一点 :   
[root@db-172-16-3-39 ~]# stap -e 'probe syscall.fork {printdln("/", execname(), pid(), tid())}'  
postgres/28144/28144  
28144进程正是postgresql主进程号.  
autovacuum 进程的唤醒时间间隔和当前集群中有多少个数据库以及配置autovacuum_naptime 有关 :   
参见autovacuum_naptime的解释 :   
autovacuum_naptime (integer)  
Specifies the minimum delay between autovacuum runs on any given database. In each round the daemon examines the database and issues VACUUM and ANALYZE commands as needed for tables in that database. The delay is measured in seconds, and the default is one minute (1min). This parameter can only be set in the postgresql.conf file or on the server command line.  
注意注解, 这个时间是autovacuum进程对每个数据库扫描的最小时间间隔. 所以autovacuum唤醒autovacuum worker的频率就等于autovacuum_naptime除以集群中数据库的个数(不包含template0和template1)  
轮询间隔为autovacuum_naptime / 数据库个数.(不包含template0以及template1)  
新建一个数据库后, 轮询时间间隔变成了20秒(现在集群中有3个数据库postgres,digoal,test), 每次探测一个数据库.  
digoal=# create database test;  
CREATE DATABASE  
test=# create table t(id int);  
CREATE TABLE  
g93@db-172-16-3-39-> ps -efw|grep postgres  
pg93      2451     1  0 15:19 pts/4    00:00:00 /home/pg93/pgsql9.3.0/bin/postgres  
pg93      2452  2451  0 15:19 ?        00:00:00 postgres: logger process            
pg93      2454  2451  0 15:19 ?        00:00:00 postgres: checkpointer process      
pg93      2455  2451  0 15:19 ?        00:00:00 postgres: writer process            
pg93      2456  2451  0 15:19 ?        00:00:00 postgres: wal writer process        
pg93      2457  2451  0 15:19 ?        00:00:00 postgres: autovacuum launcher process     
pg93      2458  2451  0 15:19 ?        00:00:00 postgres: archiver process          
pg93      2459  2451  0 15:19 ?        00:00:00 postgres: stats collector process     
stap 脚本的输出发生了一些改变, 时间间隔变了, 现在是20秒.  
6/postgres/2457/2457/2/1381389699/120218073 postgres(2457):       
8/postgres/2483/2483/1/1381389699/     0 postgres(2483):  
9/postgres/2483/2483/1/1381389699/ 10738 postgres(2483):   
7/postgres/2457/2457/2/1381389719/140316989 postgres(2457):        
10/postgres/2494/2494/1/1381389719/     0 postgres(2494):  
11/postgres/2494/2494/1/1381389719/ 10885 postgres(2494):   
8/postgres/2457/2457/2/1381389739/160316982 postgres(2457):         
12/postgres/2502/2502/1/1381389739/     0 postgres(2502):  
13/postgres/2502/2502/1/1381389739/ 10900 postgres(2502):   
9/postgres/2457/2457/2/1381389759/180316985 postgres(2457):          
14/postgres/2510/2510/1/1381389759/     0 postgres(2510):  
15/postgres/2510/2510/1/1381389759/ 10734 postgres(2510):   
再新建一个数据库 :   
digoal=# create database test1;  
CREATE DATABASE  
digoal=# \c test1  
You are now connected to database "test1" as user "postgres".  
test1=# create table t1(id int);  
CREATE TABLE  
轮询间隔变成了15秒 (现在集群中有4个数据库postgres,digoal,test,test1)  
16/postgres/2457/2457/2/1381389874/295623989 postgres(2457):                 
26/postgres/2568/2568/1/1381389874/     0 postgres(2568):  
27/postgres/2568/2568/1/1381389874/ 10733 postgres(2568):   
17/postgres/2457/2457/2/1381389889/310623979 postgres(2457):                  
28/postgres/2569/2569/1/1381389889/     0 postgres(2569):  
29/postgres/2569/2569/1/1381389889/ 10833 postgres(2569):   
18/postgres/2457/2457/2/1381389904/325623987 postgres(2457):                   
30/postgres/2585/2585/1/1381389904/     0 postgres(2585):  
31/postgres/2585/2585/1/1381389904/ 10746 postgres(2585):   
[其他]  
1. 使用cmdline_str()函数可以输出详细的命令行参数.  
如  
[root@db-172-16-3-39 utils]# stap -e 'probe process("/home/pg93/pgsql9.3.0/bin/postgres").mark("transaction__start") {printdln("/",$arg1,execname(),pid(),tid(),cpu(),gettimeofday_s(),thread_indent(1),cmdline_str()); }'  
456/postgres/5184/5184/4/1381397061/     0 postgres(5184):/postgres: postgres digoal [local] authentication  
293/postgres/2457/2457/6/1381397071/     0 postgres(2457):/postgres: autovacuum launcher process     
457/postgres/5186/5186/1/1381397071/     0 postgres(5186):/postgres: autovacuum worker process     
458/postgres/5186/5186/1/1381397071/ 10784 postgres(5186): /postgres: autovacuum worker process   postgres  
294/postgres/2457/2457/6/1381397101/29888994 postgres(2457): /postgres: autovacuum launcher process     
459/postgres/5202/5202/1/1381397101/     0 postgres(5202):/postgres: autovacuum worker process     
460/postgres/5202/5202/1/1381397101/ 10784 postgres(5202): /postgres: autovacuum worker process   digoal  
295/postgres/2457/2457/6/1381397131/60098978 postgres(2457):  /postgres: autovacuum launcher process     
461/postgres/5219/5219/1/1381397131/     0 postgres(5219):/postgres: autovacuum worker process     
462/postgres/5219/5219/1/1381397131/ 10761 postgres(5219): /postgres: autovacuum worker process   postgres  

参考

1. http://www.postgresql.org/docs/9.3/static/runtime-config-autovacuum.html

2. http://blog.163.com/digoal@126/blog/static/163877040201383044341926/

3. http://www.postgresql.org/docs/9.3/static/dynamic-trace.html

Flag Counter

digoal’s 大量PostgreSQL文章入口