Postgres的日誌實用功能

不得不說，Postgres的日誌(pg_log，相似oracle的alter文件，非pg_xlog)確實是很靈活，功能也很豐富的，下面是借用postgres的日誌來實現一些管理功能，下面涉及的參數都在文件$PGDATA/postgresql.conf裏面。

OS:CentOS 6.2
DB:Postgres 9.2.3

1.日誌審計
審計是值記錄用戶的登錄退出以及登錄後在數據庫裏的行爲操做，能夠根據安全等級不同設置不同級別的審計，
此處涉及的參數文件有：

logging_collector      --是否開啓日誌收集開關，默認off，開啓要重啓DB
log_destination    --日誌記錄類型，默認是stderr，只記錄錯誤輸出
log_directory      --日誌路徑，默認是$PGDATA/pg_log
log_filename       --日誌名稱，默認是postgresql-%Y-%m-%d_%H%M%S.log
log_connections    --用戶session登錄時是否寫入日誌，默認off
log_disconnections --用戶session退出時是否寫入日誌，默認off
log_rotation_age   --保留單個文件的最大時長,默認是1d,也有1h,1min,1s,我的以爲不實用
log_rotation_size  --保留單個文件的最大尺寸，默認是10MB

配置值：

logging_collector = on
log_destination = 'csvlog'
log_directory = '/home/postgres/pg_log'
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_connections = on
log_disconnections = on
log_rotation_age = 1d
log_rotation_size = 20MB

配置完重啓DB，檢查日誌狀況

[postgres@localhost pg_log]$ ls -l
total 4
-rw-------. 1 postgres postgres  672 Mar 29 08:25 postgresql-2013-03-29_000000.csv
-rw-------. 1 postgres postgres    0 Mar 29 00:00 postgresql-2013-03-29_000000.log
[postgres@localhost pg_log]$ 

--登錄並退出，日誌內容有訪問的IP(local),訪問用戶，登錄和退出時間等信息，對檢查超級用戶的登錄退出是頗有效的
[postgres@localhost pg_log]$ psql
psql (9.2.3)
Type "help" for help.

postgres=# \q
[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv 
2013-03-29 10:38:36.934 PDT,,,2236,"",5155d19c.8bc,1,"",2013-03-29 10:38:36 PDT,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2013-03-29 10:38:36.938 PDT,"postgres","postgres",2236,"[local]",5155d19c.8bc,2,"authentication",2013-03-29 10:38:36 PDT,2/11858,0,LOG,00000,"connection authorized: user=postgres database=postgres",,,,,,,,,""
2013-03-29 10:38:42.365 PDT,"postgres","postgres",2236,"[local]",5155d19c.8bc,3,"idle",2013-03-29 10:38:36 PDT,,0,LOG,00000,"disconnection: session time: 0:00:05.431 user=postgres database=postgres host=[local]",,,,,,,,,"psql"

記錄用戶登錄數據庫後的各類操做，postgres日誌裏分紅了3類，經過參數pg_statement來控制，默認的pg_statement參數值是none，即不記錄，能夠設置ddl(記錄create,drop和alter)、mod(記錄ddl+insert,delete,update和truncate)和all(mod+select)。

示例：
[postgres@localhost ~]$ vi $PGDATA/postgresql.conf
log_statement = ddl

postgres=# show log_statement;
 log_statement 
---------------
 ddl
(1 row)

postgres=# create table t_ken_yon(id int);
CREATE TABLE
postgres=# drop table t_ken_yon ;
DROP TABLE
postgres=# 

[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv 
2013-03-29 11:01:29.048 PDT,"postgres","postgres",2324,"[local]",5155d681.914,3,"idle",2013-03-29 10:59:29 PDT,2/11945,0,LOG,00000,"statement: create table t_ken_yon(id int);",,,,,,,,,"psql"
2013-03-29 11:01:36.087 PDT,"postgres","postgres",2324,"[local]",5155d681.914,4,"idle",2013-03-29 10:59:29 PDT,2/11948,0,LOG,00000,"statement: drop table t_ken_yon ;",,,,,,,,,"psql"

--修改成mod級別，並reload
postgres=# show log_statement;
 log_statement 
---------------
 mod
(1 row)
postgres=# insert into t_ken_yon values(1),(2);
INSERT 0 2
postgres=# delete from t_ken_yon where id =1;
DELETE 1

[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv
2013-03-29 11:04:08.148 PDT,,,5554,,514933a6.15b2,42,,2013-03-19 20:57:26 PDT,,0,LOG,00000,"received SIGHUP, reloading configuration files",,,,,,,,,""
2013-03-29 11:04:08.151 PDT,,,5554,,514933a6.15b2,43,,2013-03-19 20:57:26 PDT,,0,LOG,00000,"parameter ""log_statement"" changed to ""mod""",,,,,,,,,""
2013-03-29 11:05:33.346 PDT,"postgres","postgres",2324,"[local]",5155d681.914,6,"idle",2013-03-29 10:59:29 PDT,2/11952,0,LOG,00000,"statement: insert into t_ken_yon values(1),(2);",,,,,,,,,"psql"
2013-03-29 11:05:52.033 PDT,"postgres","postgres",2324,"[local]",5155d681.914,7,"idle",2013-03-29 10:59:29 PDT,2/11953,0,LOG,00000,"statement: delete from t_ken_yon where id =1;",,,,,,,,,"psql"

--修改成all級別，並reload
postgres=# show log_statement;
 log_statement 
---------------
 all
(1 row)

postgres=# select * from t_ken_yon;
 id 
----
  2
(1 row)

[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv 
2013-03-29 11:07:14.820 PDT,,,5554,,514933a6.15b2,44,,2013-03-19 20:57:26 PDT,,0,LOG,00000,"received SIGHUP, reloading configuration files",,,,,,,,,""
2013-03-29 11:07:14.821 PDT,,,5554,,514933a6.15b2,45,,2013-03-19 20:57:26 PDT,,0,LOG,00000,"parameter ""log_statement"" changed to ""all""",,,,,,,,,""
2013-03-29 11:07:19.784 PDT,"postgres","postgres",2324,"[local]",5155d681.914,8,"idle",2013-03-29 10:59:29 PDT,2/11954,0,LOG,00000,"statement: show log_statement;",,,,,,,,,"psql"
2013-03-29 11:07:28.631 PDT,"postgres","postgres",2324,"[local]",5155d681.914,9,"idle",2013-03-29 10:59:29 PDT,2/11955,0,LOG,00000,"statement: select * from t_ken_yon;",,,,,,,,,"psql"

通常的OLTP系統審計級別設置爲ddl就夠了，由於記錄輸出各類SQL對性能的影響仍是蠻大的，安全級別高一點的也能夠設置mod模式，有條件也能夠不在數據庫層面作，而是購買設備放在網絡層監控解析。

  2.定位慢查詢SQL
能夠設置必定時長的參數(log_min_duration_statement)，來記錄超過該時長的全部SQL，對找出當前數據庫的慢查詢頗有效。 好比log_min_duration_statement = 2s,記錄超過2秒的SQL，改完須要reload

示例:

postgres=# show log_min_duration_statement ;
 log_min_duration_statement 
----------------------------
 2s
(1 row)

postgres=# \timing 
Timing is on.
postgres=# select now(),pg_sleep(1);
             now              | pg_sleep 
------------------------------+----------
 2013-03-29 12:36:48.13353-07 | 
(1 row)

Time: 1001.844 ms
postgres=# select now(),pg_sleep(4);
              now              | pg_sleep 
-------------------------------+----------
 2013-03-29 12:36:28.309595-07 | 
(1 row)

Time: 4002.273 ms

[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv 
2013-03-29 12:36:19.265 PDT,"postgres","postgres",2324,"[local]",5155d681.914,10,"SELECT",2013-03-29 10:59:29 PDT,2/0,0,LOG,00000,"duration: 4027.183 ms  statement: select now(),pg_sleep(4);",,,,,,,,,"psql"

能夠看到只記錄了4秒的那個SQL，而沒有記錄1秒的SQL。

3.監控數據庫的checkpoint
當數據庫進行一項大更新操做時，若是參數設置不當，會在日誌裏留下大量的告警信息，頻繁的作checkpoint會致使系統變慢，如:

2013-03-28 17:01:39.523 CST,,,10350,,50bd676b.286e,1,,2012-12-04 11:00:59 CST,,0,LOG,00000,"checkpoints are occurring too frequently (8 seconds apart)",,"Consider increasing the configuration parameter ""checkpoint_segments"".",,,,,,,""
2013-03-28 17:01:50.427 CST,,,10350,,50bd676b.286e,2,,2012-12-04 11:00:59 CST,,0,LOG,00000,"checkpoints are occurring too frequently (11 seconds apart)",,"Consider increasing the configuration parameter ""checkpoint_segments"".",,,,,,,""

可是不會記錄系統正常的checkpoint，若是你想看系統一天之類發生了多少次checkpoint，以及每次checkpoint的一些詳細信息，好比buffer,sync等，就能夠經過設置log_checkpoints，該參數默認值是off，修改log_checkpoints = on 示例：

postgres=# show log_checkpoints ;
 log_checkpoints 
-----------------
 on
(1 row)
postgres=# checkpoint;
CHECKPOINT
postgres=#

[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv 
2013-03-29 12:43:38.900 PDT,,,5557,,514933a7.15b5,45,,2013-03-19 20:57:27 PDT,,0,LOG,00000,"checkpoint starting: immediate force wait",,,,,,,,,""
2013-03-29 12:43:38.941 PDT,,,5557,,514933a7.15b5,46,,2013-03-19 20:57:27 PDT,,0,LOG,00000,"checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.009 s, sync=0.000 s, total=0.040 s; sync files=0, longest=0.000 s, average=0.000 s",,,,,,,,,""

 4.監控數據庫的鎖
數據庫的鎖一般能夠在pg_locks這個系統表裏找，但這只是當前的鎖表/行信息，若是你想看一天內有多少個超過死鎖時間的鎖發生，能夠在日誌裏設置並查看，log_lock_waits 默認是off，能夠設置開啓。這個能夠區分SQL慢是資源緊張仍是鎖等待的問題。 示例:

postgres=# show log_lock_waits ;
 log_lock_waits 
----------------
 on
(1 row)

postgres=# show deadlock_timeout ;
 deadlock_timeout 
------------------
 1s
(1 row)

--模擬鎖
postgres=# begin;
BEGIN
postgres=# SELECT * FROM t_ken_yon ;
 id 
----
 11
(1 row)

postgres=# delete from t_ken_yon ;
DELETE 1

--另外一個session
postgres=# begin;
BEGIN
postgres=# delete from t_ken_yon;

--查看日誌
[postgres@localhost pg_log]$ tail -f postgresql-2013-03-29_000000.csv
2013-03-29 14:01:02.673 PDT,"postgres","postgres",3056,"[local]",5155f4d9.bf0,6,"DELETE waiting",2013-03-29 13:08:57 PDT,5/12502,2659,LOG,00000,"process 3056 still waiting for ShareLock on transaction 2658 after 1000.398 ms",,,,,,"delete from t_ken_yon;",,,"psql"
2013-03-29 14:02:06.208 PDT,"postgres","postgres",3056,"[local]",5155f4d9.bf0,7,"DELETE waiting",2013-03-29 13:08:57 PDT,5/12502,2659,LOG,00000,"process 3056 acquired ShareLock on transaction 2658 after 64535.339 ms",,,,,,"delete from t_ken_yon;",,,"psql"
2013-03-29 14:02:06.209 PDT,"postgres","postgres",3056,"[local]",5155f4d9.bf0,8,"DELETE",2013-03-29 13:08:57 PDT,5/12502,2659,LOG,00000,"duration: 64536.118 ms  statement: delete from t_ken_yon;",,,,,,,,,"psql"

還有一些Debug功能，適合修改源碼調試，通常的的系統上並不須要，暫時比較關注的就這些。