PostgreSQL 锁等待跟踪
2016-05-05 10:24
381 查看
摘要PostgreSQL 在打印LONG SQL时,锁等待的时间也会算在内,并且目前在日志中没有将锁等待的时间单独打印出来。 shared_preload_libraries='auto_explain' auto_explain.log_min_duration='1s' auto_explai...
PostgreSQL 在打印LONG SQL时,锁等待的时间也会算在内,并且目前在日志中没有将锁等待的时间单独打印出来。
例子:
查看日志如下:
等待时间也被计算在内了。
如果要分析锁等待的话,最好加上如下参数:
那么在日志中,可以看到会话等待锁的时间超过deadlock_timeout时,会打印一条日志,告诉你在等待那个PID,等待什么锁:
在获取到锁之后,又会打印一条日志:
分析以上两条日志,和long sql的日志关联起来,就可以知道LONG SQL的锁等待花了多少时间。
如果要跟踪更详细的锁信息,需要修改一下头文件,重新编译:
以上CASE,可以跟踪到如下锁信息:
锁的解释需要对照src/include/storage/lock.h
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=# update test2 set info='b' ; wait session A: postgres=# end; COMMIT session B: UPDATE 1
查看日志如下:
2016-03-15 15:44:23.618 CST,"postgres","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","postgres",106815,"[local]",56e7bc6c.1a13f,4,"UPDATE",2016-03-15 15:40:28 CST,3/0,0,LOG,00000,"duration: 32039.289 ms statement: update test2 set info='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,"postgres","postgres",10220,"[local]",56e7c3df.27ec,32,"UPDATE waiting",2016-03-15 16:12:15 CST,3/17,574614691,LOG,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,"postgres","postgres",10220,"[local]",56e7c3df.27ec,33,"UPDATE waiting",2016-03-15 16:12:15 CST,3/17,574614691,LOG,00000,"process 10220 acquired ShareLock on transaction 574614690 after 100194.020 ms",,,,,"while updating tuple (0,5) in relation ""test2""","update test2 set info='b' ;",,"ProcSleep, proc.c:1327","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,,0,LOG,00000,"connection received: host=[local]",,,,,,,,"BackendInitialize, postmaster.c:4081","" 2016-03-15 16:12:08.390 CST,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,2,"authentication",2016-03-15 16:12:08 CST,2/11,0,LOG,00000,"connection authorized: user=postgres database=postgres",,,,,,,,"PerformAuthentication, postinit.c:259","" 2016-03-15 16:12:08.391 CST,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,3,"startup",2016-03-15 16:12:08 CST,2/0,0,LOG,00000,"LockReleaseAll: lockmethod=1",,,,,,,,"LockReleaseAll, lock.c:1951","psql" 2016-03-15 16:12:08.391 CST,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,4,"startup",2016-03-15 16:12:08 CST,2/0,0,LOG,00000,"LockReleaseAll done",,,,,,,,"LockReleaseAll, lock.c:2198","psql" 2016-03-15 16:12:13.968 CST,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,5,"UPDATE",2016-03-15 16:12:08 CST,2/12,0,LOG,00000,"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,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,6,"UPDATE",2016-03-15 16:12:08 CST,2/12,0,LOG,00000,"LockAcquire: lock [13241,53029] RowExclusiveLock",,,,,,"update test2 set info='a' where id=1;",,"LockAcquireExtended, lock.c:724","psql" 2016-03-15 16:12:15.815 CST,,,10220,"",56e7c3df.27ec,1,"",2016-03-15 16:12:15 CST,,0,LOG,00000,"connection received: host=[local]",,,,,,,,"BackendInitialize, postmaster.c:4081","" 2016-03-15 16:12:15.816 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,2,"authentication",2016-03-15 16:12:15 CST,3/15,0,LOG,00000,"connection authorized: user=postgres database=postgres",,,,,,,,"PerformAuthentication, postinit.c:259","" 2016-03-15 16:12:15.817 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,3,"startup",2016-03-15 16:12:15 CST,3/0,0,LOG,00000,"LockReleaseAll: lockmethod=1",,,,,,,,"LockReleaseAll, lock.c:1951","psql" 2016-03-15 16:12:15.817 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,4,"startup",2016-03-15 16:12:15 CST,3/0,0,LOG,00000,"LockReleaseAll done",,,,,,,,"LockReleaseAll, lock.c:2198","psql" 2016-03-15 16:12:16.777 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,5,"UPDATE",2016-03-15 16:12:15 CST,3/16,0,LOG,00000,"LockAcquire: lock [13241,53029] RowExclusiveLock",,,,,,"update test2 set info='b' ;",8,"LockAcquireExtended, lock.c:724","psql" 2016-03-15 16:12:16.778 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,6,"UPDATE",2016-03-15 16:12:15 CST,3/16,0,LOG,00000,"LockAcquire: lock [13241,53029] RowExclusiveLock",,,,,,"update test2 set info='b' ;",,"LockAcquireExtended, lock.c:724","psql" 2016-03-15 16:12:16.778 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,7,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockAcquire: lock [13241,53029] ExclusiveLock",,,,,,"update test2 set info='b' ;",,"LockAcquireExtended, lock.c:724","psql" 2016-03-15 16:12:16.778 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,8,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockAcquire: new: lock(0x7f88ead65ed8) id(13241,53029,0,3,3,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(ExclusiveLock)",,,,,,"update test2 set info='b' ;",,"LOCK_PRINT, lock.c:319","psql" 2016-03-15 16:12:16.778 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,9,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockAcquire: new: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",,,,,,"update test2 set info='b' ;",,"PROCLOCK_PRINT, lock.c:331","psql" 2016-03-15 16:12:16.778 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,10,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockCheckConflicts: no conflict: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",,,,,,"update test2 set info='b' ;",,"PROCLOCK_PRINT, lock.c:331","psql" 2016-03-15 16:12:16.778 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,11,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"GrantLock: lock(0x7f88ead65ed8) id(13241,53029,0,3,3,1) grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) type(ExclusiveLock)",,,,,,"update test2 set info='b' ;",,"LOCK_PRINT, lock.c:319","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,7,"COMMIT",2016-03-15 16:12:08 CST,2/0,574614688,LOG,00000,"LockReleaseAll: lockmethod=1",,,,,,"end;",,"LockReleaseAll, lock.c:1951","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",9725,"[local]",56e7c3d8.25fd,8,"COMMIT",2016-03-15 16:12:08 CST,2/0,574614688,LOG,00000,"LockReleaseAll done",,,,,,"end;",,"LockReleaseAll, lock.c:2198","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,12,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockRelease: lock [13241,53029] ExclusiveLock",,,,,,"update test2 set info='b' ;",,"LockRelease, lock.c:1758","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,13,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockRelease: found: lock(0x7f88ead65ed8) id(13241,53029,0,3,3,1) grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) type(ExclusiveLock)",,,,,,"update test2 set info='b' ;",,"LOCK_PRINT, lock.c:319","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,14,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockRelease: found: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(80)",,,,,,"update test2 set info='b' ;",,"PROCLOCK_PRINT, lock.c:331","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,15,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"UnGrantLock: updated: lock(0x7f88ead65ed8) id(13241,53029,0,3,3,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(ExclusiveLock)",,,,,,"update test2 set info='b' ;",,"LOCK_PRINT, lock.c:319","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,16,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"UnGrantLock: updated: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",,,,,,"update test2 set info='b' ;",,"PROCLOCK_PRINT, lock.c:331","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,17,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"CleanUpLock: deleting: proclock(0x7f88eadf4878) lock(0x7f88ead65ed8) method(1) proc(0x7f88eb0211f0) hold(0)",,,,,,"update test2 set info='b' ;",,"PROCLOCK_PRINT, lock.c:331","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,18,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"CleanUpLock: deleting: lock(0x7f88ead65ed8) id(13241,53029,0,3,3,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)",,,,,,"update test2 set info='b' ;",,"LOCK_PRINT, lock.c:319","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,19,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockAcquire: lock [13241,53029] AccessShareLock",,,,,,"update test2 set info='b' ;",,"LockAcquireExtended, lock.c:724","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,20,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"LockRelease: lock [13241,53029] AccessShareLock",,,,,,"update test2 set info='b' ;",,"LockRelease, lock.c:1758","psql" 2016-03-15 16:17:05.528 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,21,"UPDATE",2016-03-15 16:12:15 CST,3/16,574614689,LOG,00000,"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",,,,,,,,"explain_ExecutorEnd, auto_explain.c:333","psql" 2016-03-15 16:17:05.529 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,22,"UPDATE",2016-03-15 16:12:15 CST,3/0,574614689,LOG,00000,"LockReleaseAll: lockmethod=1",,,,,,"update test2 set info='b' ;",,"LockReleaseAll, lock.c:1951","psql" 2016-03-15 16:17:05.529 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,23,"UPDATE",2016-03-15 16:12:15 CST,3/0,574614689,LOG,00000,"LockReleaseAll done",,,,,,"update test2 set info='b' ;",,"LockReleaseAll, lock.c:2198","psql" 2016-03-15 16:17:05.529 CST,"postgres","postgres",10220,"[local]",56e7c3df.27ec,24,"UPDATE",2016-03-15 16:12:15 CST,3/0,0,LOG,00000,"duration: 288751.635 ms statement: update test2 set info='b' ;",,,,,,,,"exec_simple_query, postgres.c:1181","psql"
锁的解释需要对照src/include/storage/lock.h
相关文章推荐
- oracle物化视图日志结构
- Oracle性能优化-读懂执行计划
- Oracle如何根据物化视图日志快速刷新物化视图
- Oracle性能优化-读懂执行计划
- SQL Server 别名数据类型
- Oracle物化视图语法
- SQL Server-- 存储过程中错误处理
- Oracle存储过程的异常处理
- Oracle数据导入与导出
- Jedis对于Redis的使用(一)
- MySQL 数据库 varchar 到底可以存多少个汉字,多少个英文呢?我们来搞搞清楚
- SQL Server 2012将数据导出为脚本详细图解
- mysql二进制类型
- 常用Oracle语句
- mysql索引总结----mysql 索引类型以及创建
- SQL Server中row_number的用法
- Django笔记:2.数据库的建立
- EAS收集KSQL日志的方法
- iOS中sqlite的详细用法
- C#串口采集短信GSM chart图表使用示例 保存数据到access数据库和每日.txt文件并实时显示各参数曲线