PostgreSQL 在打印LONG SQL时，锁等待的时间也会算在内，并且目前在日志中没有将锁等待的时间单独打印出来。
shared_preload_libraries='auto_explain'
auto_explain.log_min_duration='1s'
auto_explain.log_analyze=true
auto_explain.log_buffers=true
auto_explain.log_timing=true
auto_explain.log_triggers=true
auto_explain.log_verbose=true
auto_explain.log_nested_statements=true
pg_ctl restart -m fast
例子:
session A:
postgres=# create table test2(id int,info text);
CREATE TABLE postgres=# insert into test2 values (1,'test');
INSERT 0 1 postgres=# begin;
BEGIN postgres=# update test2 set info='a' where id=1;
UPDATE 1 session B: postgres=# 'b' ;
wait
session A:
postgres=# end;
COMMIT session B: 1
查看日志如下：
2016-03-15 15:44:23.618 CST,"postgres",106815,"[local]",56e7bc6c.1a13f,3,"UPDATE",2016-03-15 15:40:28 CST,3/12,574614687,LOG,00000,"duration: 32038.420 ms plan: Query Text: 'b' ;
Update on test2 (cost=0.00..22.70 rows=1270 width=10) (actual time=32038.418..32038.418 0 loops=1) Buffers: shared hit=5 -> Seq Scan 0.014..0.015 1 loops=1explain_ExecutorEnd,auto_explain.c:333psql" 2016-03-15 15:44:23.618 CST,"postgres[local]32039.289 ms statement: 'b' ;","exec_simple_query,postgres.c:1181","psql"
等待时间也被计算在内了。
如果要分析锁等待的话，最好加上如下参数：
log_lock_waits = on
deadlock_timeout = 1s
那么在日志中，可以看到会话等待锁的时间超过deadlock_timeout时，会打印一条日志，告诉你在等待那个PID，等待什么锁：
2016-03-15 16:30:57.129 CST,116)">"postgres",10220,116)">"[local]",255)">56e7c3df.27ec,255)">32,116)">"UPDATE waiting",255)">12:15 CST,255)">3/17,255)">574614691,255)">00000,116)">"process 10220 still waiting for ShareLock on transaction 574614690 after 1000.036 ms",116)">"Process holding the lock: 9725. Wait queue: 10220.",116)">"while updating tuple (0,5) in relation ""test2""",116)">"update test2 set info='b' ;",116)">"ProcSleep,proc.c:1323",116)">"psql"
在获取到锁之后，又会打印一条日志：
32:36.323 CST,255)">33,116)">"process 10220 acquired ShareLock on transaction 574614690 after 100194.020 ms",proc.c:1327",116)">"psql"
分析以上两条日志，和long sql的日志关联起来，就可以知道LONG SQL的锁等待花了多少时间。
如果要跟踪更详细的锁信息，需要修改一下头文件，重新编译：
vi src/include/pg_config_manual.h
#define LOCK_DEBUG
make clean
make distclean
configure again
make -j 32
make install -j 32
vi $PGDATA/postgresql.conf
trace_locks = true
pg_ctl restart -m fast
以上CASE，可以跟踪到如下锁信息：
2016-03-15 16:12:08.389 CST,9725,"",56e7c3d8.25fd,1,2016-03-15 16:12:08 CST,"connection received: host=[local]","BackendInitialize,postmaster.c:4081",""
2016-03-15 16:12:08.390 CST,2,"authentication",2/11,"connection authorized: user=postgres database=postgres","PerformAuthentication,postinit.c:259",""
2016-03-15 16:12:08.391 CST,"startup",2/0,"LockReleaseAll: lockmethod=1","LockReleaseAll,lock.1951" 2016-03-15 16:12:08.391 CST,114)">startupLockReleaseAll doneLockReleaseAll,2198" 2016-03-15 16:12:13.968 CST,5,2/12,"LockAcquire: lock [13241,255)">53029] RowExclusiveLock1;",8,"LockAcquireExtended,255)">724" 2016-03-15 16:12:13.969 CST,6,116)">" 2016-03-15 16:12:15.815 CST,10220,56e7c3df.27ec,2016-03-15 16:12:15 CST,114)">connection received: host=[BackendInitialize,postmaster.4081authenticationconnection authorized: user=postgres database=postgresPerformAuthentication,postinit.259LockReleaseAll: lockmethod=" 2016-03-15 16:12:15.817 CST,116)">" 2016-03-15 16:12:16.777 CST,3/16,116)">" 2016-03-15 16:12:16.778 CST,7,574614689,255)">53029] ExclusiveLocknew: lock(0x7f88ead65ed8) id(53029,255)">0,255)">3,255)">1) grantMask(0) req(0)=0 grant(wait(0) type(ExclusiveLock)319new: proclock(0x7f88eadf4878) 0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)331LockCheckConflicts: no conflict: proclock(GrantLock: 80) req(1)=" 2016-03-15 16:17:05.528 CST,114)">COMMITend;",12,"LockRelease: 1758found: found: proclock(80)UnGrantLock: updated: updated: proclock(CleanUpLock: deleting: proclock(CleanUpLock: deleting: type(INVALID)53029] AccessShareLock288750.628 ms plan: 288750.624..288750.624 0.013." 2016-03-15 16:17:05.529 CST,22,23,24,255)">288751.635 ms
锁的解释需要对照src/include/storage/lock.h
