PostgreSQL 锁等待跟踪_sql

概述摘要 PostgreSQL 在打印LONG SQL时，锁等待的时间也会算在内，并且目前在日志中没有将锁等待的时间单独打印出来。 shared_preload_libraries='auto_explain' auto_explain.log_min_duration='1s' auto_explai... PostgreSQL 在打印LONG SQL时，锁等待的时间也会算在内，并且目前在日志中没有摘要 Postgresql 在打印LONG sql时，锁等待的时间也会算在内，并且目前在日志中没有将锁等待的时间单独打印出来。 shared_preload_librarIEs='auto_explain' auto_explain.log_min_duration='1s' auto_explai...

Postgresql 在打印LONG sql时，锁等待的时间也会算在内，并且目前在日志中没有将锁等待的时间单独打印出来。

shared_preload_librarIEs='auto_explain'auto_explain.log_min_duration='1s'auto_explain.log_analyze=trueauto_explain.log_buffers=trueauto_explain.log_timing=trueauto_explain.log_triggers=trueauto_explain.log_verbose=trueauto_explain.log_nested_statements=truepg_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=# update test2 set info='b' ;waitsession A:postgres=# end;COMMIT session B: UPDATE 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: update test2 set info='b' ;Update on test2 (cost=0.00..22.70 rows=1270 wIDth=10) (actual time=32038.418..32038.418 rows=0 loops=1) Buffers: shared hit=5 -> Seq Scan on test2 (cost=0.00..22.70 rows=1270 wIDth=10) (actual time=0.014..0.015 rows=1 loops=1) Buffers: shared hit=1","explain_ExecutorEnd,auto_explain.c:333","psql" 2016-03-15 15:44:23.618 CST,"postgres","[local]",4,"UPDATE",3/0,"duration: 32039.289 ms statement: update test2 set info='b' ;","exec_simple_query,postgres.c:1181","psql"

等待时间也被计算在内了。

如果要分析锁等待的话，最好加上如下参数：

log_lock_waits = ondeadlock_timeout = 1s

那么在日志中，可以看到会话等待锁的时间超过deadlock_timeout时，会打印一条日志，告诉你在等待那个PID，等待什么锁：

2016-03-15 16:30:57.129 CST,"postgres",10220,"[local]",56e7c3df.27ec,32,"UPDATE waiting",2016-03-15 16:12:15 CST,3/17,574614691,00000,"process 10220 still waiting for ShareLock on transaction 574614690 after 1000.036 ms","Process holding the lock: 9725. Wait queue: 10220.","while updating tuple (0,5) in relation ""test2""","update test2 set info='b' ;","Procsleep,proc.c:1323","psql"

在获取到锁之后，又会打印一条日志：

2016-03-15 16:32:36.323 CST,33,"process 10220 acquired ShareLock on transaction 574614690 after 100194.020 ms",proc.c:1327","psql"

分析以上两条日志，和long sql的日志关联起来，就可以知道LONG sql的锁等待花了多少时间。

如果要跟踪更详细的锁信息，需要修改一下头文件，重新编译：

vi src/include/pg_config_manual.h#define LOCK_DEBUGmake cleanmake distcleanconfigure againmake -j 32make install -j 32vi $PGDATA/postgresql.conftrace_locks = truepg_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.c:1951","psql" 2016-03-15 16:12:08.391 CST,"startup","LockReleaseAll done","LockReleaseAll,lock.c:2198","psql" 2016-03-15 16:12:13.968 CST,5,2/12,"LockAcquire: lock [13241,53029] RowExclusiveLock","update test2 set info='a' where ID=1;",8,"LockAcquireExtended,lock.c:724","psql" 2016-03-15 16:12:13.969 CST,6,"psql" 2016-03-15 16:12:15.815 CST,10220,56e7c3df.27ec,2016-03-15 16:12:15 CST,"connection received: host=[local]","BackendInitialize,postmaster.c:4081","" 2016-03-15 16:12:15.816 CST,"authentication",3/15,"connection authorized: user=postgres database=postgres","PerformAuthentication,postinit.c:259","" 2016-03-15 16:12:15.817 CST,"LockReleaseAll: lockmethod=1",lock.c:1951","psql" 2016-03-15 16:12:15.817 CST,"psql" 2016-03-15 16:12:16.777 CST,3/16,"update test2 set info='b' ;","psql" 2016-03-15 16:12:16.778 CST,7,574614689,53029] ExclusiveLock","LockAcquire: new: lock(0x7f88ead65ed8) ID(13241,53029,0,3,1) grantMask(0) req(0,0)=0 grant(0,0)=0 wait(0) type(ExclusiveLock)","LOCK_PRINT,lock.c:319",9,"LockAcquire: new: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)","PROCLOCK_PRINT,lock.c:331",10,"LockCheckConflicts: no conflict: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",11,"GrantLock: lock(0x7f88ead65ed8) ID(13241,1) grantMask(80) req(0,1)=1 grant(0,1)=1 wait(0) type(ExclusiveLock)","psql" 2016-03-15 16:17:05.528 CST,"COMMIT",574614688,"end;",lock.c:2198",12,"LockRelease: lock [13241,"LockRelease,lock.c:1758",13,"LockRelease: found: lock(0x7f88ead65ed8) ID(13241,14,"LockRelease: found: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(80)",15,"UnGrantLock: updated: lock(0x7f88ead65ed8) ID(13241,16,"UnGrantLock: updated: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",17,"CleanUpLock: deleting: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",18,"CleanUpLock: deleting: lock(0x7f88ead65ed8) ID(13241,0)=0 wait(0) type(INVALID)",19,53029] AccessShareLock",20,21,"duration: 288750.628 ms plan: query Text: update test2 set info='b' ;Update on test2 (cost=0.00..22.70 rows=1270 wIDth=10) (actual time=288750.624..288750.624 rows=0 loops=1) Buffers: shared hit=5 -> Seq Scan on test2 (cost=0.00..22.70 rows=1270 wIDth=10) (actual time=0.013..0.015 rows=1 loops=1) Buffers: shared hit=1","psql" 2016-03-15 16:17:05.529 CST,22,23,24,"duration: 288751.635 ms statement: update test2 set info='b' ;","psql"