One of the great features added in PostgreSQL 8.4 is auto_explain, documented at http://www.postgresql.org/docs/current/static/auto-explain.html.
This is a contrib module, not necessarily installed by default. See the discussion of the contrib modules in Chapter 1, PostgreSQL Versions.
To enable the feature, edit your postgresql.conf to add parameters such as this:
shared_preload_libraries = 'auto_explain'
custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = '1s'
That will trigger auto_explain on any query longer than a second. You'll need to completely restart the server after making this change before it goes into effect.
Once that's done, any query that takes longer than this will be logged with a full EXPLAIN plan for the output. This is what one of the common slow pgbench UPDATE statements look like:
duration: 1955.811 ms plan:
Query Text: UPDATE pgbench_accounts SET abalance = abalance + -3410
WHERE aid = 9011517;
Update (cost=0.00..10.03 rows=1 width=103)
-> Index Scan using pgbench_accounts_pkey on pgbench_accounts
(cost=0.00..10.03 rows=1 width=103)
Index Cond: (aid = 9011517)",,,,,,,,,""
The plans will be spread across multiple lines if in the regular logs, but will be in a single column if loaded into a CSV format log. The syslog logs will also tag the multiple line output appropriately.
As for what you can use this for, a look at the logs shows the delay is happening even when updating the tiny branches table:
duration: 1490.680 ms plan:
Query Text: UPDATE pgbench_branches SET bbalance = bbalance + -2792
WHERE bid = 4;
Update (cost=0.00..4.50 rows=1 width=370)
-> Seq Scan on pgbench_branches (
cost=0.00..4.50 rows=1 width=370)
Filter: (bid = 4)",,,,,,,,,""
Knowing information like this--that the UPDATE hang is happening even when updating a table extremely likely to be in the buffer cache--is extremely valuable for tracking down the true cause of slow statements.