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=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 1session B:
postgres=# update test2 set info='b' ;
waitsession A:
postgres=# end;
COMMITsession 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_DEBUGmake clean
make distclean
configure again
make -j 32
make install -j 32vi $PGDATA/postgresql.conf
trace_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,,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

PostgreSQL 锁等待跟踪相关推荐

  1. PostgreSQL 锁等待诊断详解

    PostgreSQL和大多数传统RDBMS一样,都设计了大量的锁来保证并发操作的数据一致性. 同时PG在设计锁等待时,以队列方式存储等待锁. 参考 ProcSleep()@src/backend/st ...

  2. postgresql 锁_PostgreSQL中的锁：3.其他锁

    postgresql 锁 object-level locks (specifically, relation-level locks), as well as 对象级别的锁 (特别是关系级别的锁), ...

  3. MySQL和PGSQL事务锁等待超时时间

    问题出现的场景: 在消息队列处理消息时,同一事务内先后对同一条数据进行了插入和更新操作; 多台服务器操作同一数据库: 瞬时出现高并发现象: 导致数据更新或新增后数据经常自动回滚:表操作总报 Lock ...

  4. SQL 各种锁等待类型 wait type--sys.dm_os_wait_stats 表

    返回执行的线程所遇到的所有等待的相关信息.可以使用该聚合视图来诊断 SQL Server 以及特定查询和批处理的性能问题. 列名 数据类型 说明 wait_type nvarchar(60) 等待类型 ...

  5. postgresql锁的冲突检测 死锁检测

    一.锁的冲突检测 在PG中如果申请的锁是强锁,或者已经有其他进程对表加了强锁,如要将本地锁表中的所有锁注册到共享锁表(主锁表)中进行冲突检测,来决定当前申请的锁是否需要等待. PG对每一级表锁都设置一 ...

  6. PostgreSQL 锁表

    PostgreSQL 锁表解决 解决 一. 碰到的问题:Navicat删除表是一直转圈 出现问题的原因:短时间多次对同一张表进行查询造成表死锁 解决思路:通过查询进程把锁住的pid查出来然后解锁: 1 ...

  7. mysql 查看等待事件_PostgreSQL等待事件-锁等待分析

    阅读使人充实,讨论使人敏捷,写作使人精确.DB印象推荐搜索PostgreSQLOracleMySQL分布式>>>锁等待处理概述锁等待是我们比较常见的问题,无论是Oracle.MySQ ...

  8. MDL--元数据锁的锁请求与锁等待+元数据锁类对象

    1 元数据锁的锁请求与锁等待 元数据锁在MySQL Server层,依照锁的状态被细分为两种.一种是已经施加的锁.一种是等待施加的锁即锁请求,这样被区分的原因,如MySQL对"class M ...

  9. 一个锁等待现象的诊断案例

    作者:苏坡 袋鼠云云服务部-DBA团队 数据库工程师 前两日与一个客户交流, 客户提出了一些 对mysql隔离级别以及锁的疑问, 然后问到了出现锁等待现象的排查思路. 这不禁让我回想起 long lo ...

最新文章

  1. 报告解读 | 实现智能制造的五大关键环节和四大赋能路径
  2. SQL Server-聚焦INNER JOIN AND IN性能分析（十四）
  3. 前端如何获取联通积分_怎么利用定制的小程序来获取流量
  4. 活期储蓄账目管理系统
  5. 何恺明组《Designing Network Design Spaces》的整体解读（一篇更比六篇强）
  6. 一个例子说明数据库union all的作用
  7. LupoScan | 实景化点云数据处理软件
  8. Cadence Orcad capture导出像Visio规格的图纸图文教程及视频演示
  9. 【3阶范德蒙行列式计算】
  10. 计算机播放音乐自录,如何录制电脑内部播放的声音及音乐
  11. 区块链供应链金融实战3
  12. 基于.NetCore开发博客项目 StarBlog - (12) Razor页面动态编译
  13. 亚马逊echo中国使用_我需要Amazon Echo才能使用Alexa吗？
  14. CSS实现文字动画炫酷效果
  15. oracle数据库数据备份
  16. 搜狗云输入法、Google手机语音搜索：两款创新云产品
  17. 树莓派的mjpeg-streamer实现简单的监控功能
  18. 洛谷P1498 南蛮图腾（递归，找规律）
  19. leek()函数使用
  20. 【2021-11-07 最新python】 pixabay 图片网站全量爬虫 代码分享

热门文章

  1. c语言2048代码linux,C语言2048小游戏课设（附源码）.doc
  2. 如何使用Python进行单元测试
  3. 什么软件可以测试电脑硬件兼容性,Windows 7常用48款软件兼容性测试
  4. oracle进行日志切换,Oracle存档日志切换案例操作
  5. mel加载一个物体不同姿态的模型实现动画效果
  6. jupyetr notebook添加anaconda虚拟环境内核(tensorflow+pytorch)
  7. 实现一维卷积神经网络
  8. 深度学习训练和推理有何不同？
  9. php 取一条数据,php 读取txt 每次固定输出一条数据用什么方法实现？
  10. java for mat,在Java绑定中通过OpenCV Mat进行循环