Posts tagged ‘logging’

18 May, 2015

Simple test for lock_waits log messages

by gorthx

I do a lot of “is this !#@(* really working correctly” testing. (See also: simple test for autovacuum log messages.)

Here’s a simple test to verify that log_lock_waits is configured correctly. This is essential for troubleshooting lock contention.


-- verify settings
-- log_lock_waits should be 'on'; it is off by default.
SHOW log_lock_waits;
-- lock_wait messages are LOG level messages,
-- so the default value 'warning' should suffice here
SHOW log_min_messages;
-- if you're reading this, this is most likely still set to the default 1s. That is ok. :)
SHOW deadlock_timeout;

DROP TABLE IF EXISTS lock_wait_test;
CREATE TABLE lock_wait_test
(id serial primary key
, name text)
;

-- add some data
INSERT INTO lock_wait_test(name)
VALUES
('ankeny'),('burnside'),('couch'),('davis'),('everett'),('flanders'),('glisan'),('hoyt'),('irving')
;

-- take a lock
BEGIN;
LOCK lock_wait_test IN ACCESS EXCLUSIVE MODE;

-- open up another session and run this:
SELECT * FROM lock_wait_test;

Wait deadlock_timeout, then cancel your select query.

Then go check the logs. You should have a helpful message about your lock wait, and the waiting query:
2015-05-02 16:59:23 PDT LOG: process 7617 still waiting for AccessShareLock on relation 16550 of database 12066 after 1000.161 ms at character 15
2015-05-02 16:59:23 PDT STATEMENT: select * FROM lock_wait_test;

Roll your lock back, and repeat starting with taking a lock. Instead of canceling the SELECT query, roll back your lock. This time you’ll see these messages:
2015-05-02 17:02:23 PDT LOG: process 7617 still waiting for AccessShareLock on relation 16550 of database 12066 after 1000.112 ms at character 15
2015-05-02 17:02:23 PDT STATEMENT: select * FROM lock_wait_test;
2015-05-02 17:02:26 PDT LOG: process 7617 acquired AccessShareLock on relation 16550 of database 12066 after 3920.210 ms at character 15
2015-05-02 17:02:26 PDT STATEMENT: select * FROM lock_wait_test



Thanks to Magnus for the suggestion.

5 July, 2013

postgresql.conf: rudimentary log settings, annotated

by gorthx

One of the first changes I make in a new Postgres install is to enable activity logging. This way, if I encounter some problems down the the road, I’ve already got some data collected that may help me troubleshoot.

Here are my basic settings:

# enable logging, of course:
log_destination = 'stderr'
logging_collector = on

# target directory, on its own mount point if you can do it
log_directory = '/pg_log'

# I just use the default here
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'

# log_line_prefix in pgbadger-compatible format
# timestamp [pid]: line_number user application remote_host_&_port database %
log_line_prefix = '%t [%p]: [%l-1] %u %a %r %d %%'

# so I know when people are tinkering
log_statement = 'ddl'

# pre-emptive troubleshooting items
log_checkpoints = on

# log all statements that take longer than 10 minutes
# YMMV here - adjust for your application
log_min_duration_statement = 10min

# keep track of longer-running autovac jobs; may indicate that I need to tweak my autovacuum settings
# again, YMMV
log_autovacuum_min_duration = 10min

# again, I want to keep track of these; can be a harbinger of problems
# you may need to adjust your deadlock_timeout
log_lock_waits = on

# translates an IP to a hostname.
# Useful, but can cause problems on high-activity systems, so use with caution.
log_hostname = on

What are your favorite log settings?

12 April, 2013

Followup to some questions about the Postgres activity log

by gorthx

Answers to three questions that have come up from my various logging & monitoring talks over the years:

1. I recommend putting your activity logs on their own partition, just like you would with the transaction logs and your data directory. Rob W asked “What happens when the logger runs out of space?” The answer: nothing drastic. Postgres won’t write any more log entries, but the database will stay up. Make sure you have appropriate monitoring in place to alert you if that partition fills up.

2. “Can you set multiple log_destinations?” Well, I’ve logged to csv + stderr and csv + eventlog, just to see if it could be done. I don’t know what would happen if you tried csv + syslog.

3. “Can you set the logging GUCs on a per-database level?” Yes, some of them can be set to different values per-database or per-user, even. This can be quite useful to answer, for example, the “I don’t think your application is sending the SQL statements you think it’s sending” type of questions:

— for a specific database:
ALTER DATABASE tedsdb SET log_statement = 'all';
— for a specific user:
ALTER ROLE bill SET log_statement = 'all';

To undo this change:
ALTER ROLE bill SET log_statement = default;
or
ALTER ROLE bill RESET log_statement;

To check the settings for the database, join pg_db_role_setting, pg_database, and pg_authid:
postgres=# SELECT d.datname, COALESCE(r.rolname, 'ALL') AS rolname, s.setconfig
FROM pg_database d
JOIN pg_db_role_setting s
ON s.setdatabase = d.oid
LEFT JOIN pg_authid r
ON s.setrole = r.oid;
datname | rolname | setconfig
---------+---------+---------------------
tedsdb | ALL | {log_statement=all}

To check the settings for a particular user, look in pg_roles:
postgres=# SELECT rolname, rolconfig
FROM pg_roles
ORDER BY rolname;
rolname | rolconfig
----------+---------------------
bill | {log_statement=all}
postgres |