Wednesday, January 11, 2012

Postgresql - monitoring. log_statement (mod)

That option enables logging (like the auditing feature in Oracle) in this way:
mod logs all ddl statements, plus data-modifying statements such as INSERT, UPDATE, DELETE, TRUNCATE, and COPY FROM. PREPARE, EXECUTE, and EXPLAIN ANALYZE statements are also logged if their contained command is of an appropriate type.

This is what there is to know about this setting from the pg_settings view:

name       | log_statement
setting    | mod
unit       | 
category   | Reporting and Logging / What to Log
short_desc | Sets the type of statements logged.
extra_desc | 
context    | superuser
vartype    | enum
source     | configuration file
min_val    | 
max_val    | 
enumvals   | {none,ddl,mod,all}
boot_val   | none
reset_val  | mod
sourcefile | /var/lib/pgsql/pitr1/postgresql.conf
sourceline | 400

side note about the superuser context:
superuser
These settings can be set from postgresql.conf, or within a session via the SET command; but only superusers can change them via SET. Changes in postgresql.conf will affect existing sessions only if no session-local value has been established with SET.

http://www.postgresql.org/docs/current/static/view-pg-settings.html

I'm experimenting with PITR, and I'll need to know up to what point to recover. Ideally just before the deletion of some important data.

Then I execute , some ddl operations to test that they're effectively being logged:

postgres@linux-2561:~/pitr1/pg_log> pgbench -c 4 -j 2 -s 10 -t 10 -p 5433 pgbenchdb
Scale option ignored, using pgbench_branches table count = 10
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 10
query mode: simple
number of clients: 4
number of threads: 2
number of transactions per client: 10
number of transactions actually processed: 40/40
tps = 30.567626 (including connections establishing)
tps = 30.718934 (excluding connections establishing)

And see that effectively they where logged:
postgres@linux-2561:~/pitr1/pg_log> tail -f postgresql-2012-01-11_125210.csv
2012-01-11 13:08:14.660 CST,"postgres","pgbenchdb",10577,"[local]",4f0dde1d.2951,38,"idle in transaction",2012-01-11 13:08:13 CST,2/59,2516,LOG,00000,"statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3973 WHERE tid = 15;",,,,,,,,,""
2012-01-11 13:08:14.660 CST,"postgres","pgbenchdb",10577,"[local]",4f0dde1d.2951,39,"idle in transaction",2012-01-11 13:08:13 CST,2/59,2516,LOG,00000,"statement: UPDATE pgbench_branches SET bbalance = bbalance + -3973 WHERE bid = 3;",,,,,,,,,""
2012-01-11 13:08:14.661 CST,"postgres","pgbenchdb",10577,"[local]",4f0dde1d.2951,40,"idle in transaction",2012-01-11 13:08:13 CST,2/59,2516,LOG,00000,"statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (15, 3, 286453, -3973, CURRENT_TIMESTAMP);",,,,,,,,,""
2012-01-11 13:08:14.683 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,34,"idle in transaction",2012-01-11 13:08:13 CST,4/10,2517,LOG,00000,"statement: UPDATE pgbench_tellers SET tbalance = tbalance + 1104 WHERE tid = 94;",,,,,,,,,""
2012-01-11 13:08:14.683 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,35,"idle in transaction",2012-01-11 13:08:13 CST,4/10,2517,LOG,00000,"statement: UPDATE pgbench_branches SET bbalance = bbalance + 1104 WHERE bid = 10;",,,,,,,,,""
2012-01-11 13:08:14.683 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,36,"idle in transaction",2012-01-11 13:08:13 CST,4/10,2517,LOG,00000,"statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (94, 10, 413230, 1104, CURRENT_TIMESTAMP);",,,,,,,,,""
2012-01-11 13:08:14.708 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,37,"idle in transaction",2012-01-11 13:08:13 CST,4/11,0,LOG,00000,"statement: UPDATE pgbench_accounts SET abalance = abalance + 2487 WHERE aid = 112736;",,,,,,,,,""
2012-01-11 13:08:14.724 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,38,"idle in transaction",2012-01-11 13:08:13 CST,4/11,2518,LOG,00000,"statement: UPDATE pgbench_tellers SET tbalance = tbalance + 2487 WHERE tid = 85;",,,,,,,,,""
2012-01-11 13:08:14.725 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,39,"idle in transaction",2012-01-11 13:08:13 CST,4/11,2518,LOG,00000,"statement: UPDATE pgbench_branches SET bbalance = bbalance + 2487 WHERE bid = 2;",,,,,,,,,""
2012-01-11 13:08:14.725 CST,"postgres","pgbenchdb",10579,"[local]",4f0dde1d.2953,40,"idle in transaction",2012-01-11 13:08:13 CST,4/11,2518,LOG,00000,"statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (85, 2, 112736, 2487, CURRENT_TIMESTAMP);",,,,,,,,,""

In a more structured fashion (setting up the log as a foreign table):

postgres=# select * from pglog where message like '%UPDATE%';

log_time               | 2012-01-11 13:38:34.642-06
user_name              | postgres
database_name          | pgbenchdb
process_id             | 12719
connection_from        | [local]
session_id             | 4f0de53a.31af
session_line_num       | 1
command_tag            | idle in transaction
session_start_time     | 2012-01-11 13:38:34-06
virtual_transaction_id | 5/1216
transaction_id         | 0
error_severity         | LOG
sql_state_code         | 00000
message                | statement: UPDATE pgbench_accounts SET abalance = abalance + 2131 WHERE aid = 423974;
detail                 | 
hint                   | 
internal_query         | 
internal_query_pos     | 
context                | 
query                  | 
query_pos              | 
location               | 
application_name       |


Now, there's no place for doubts about who did what.

Source:
http://www.postgresql.org/docs/9.1/static/runtime-config-logging.html

Other references:
http://sharingtechknowledge.blogspot.com/2012/01/postgresql-foreign-tables-filefdw.html

Now, in a busy system having such granular level of logging will generate huge logs, so specifying a log rotation setting is a must.

No comments:

Post a Comment