PostgreSQL 锁等待跟踪

本文涉及的产品
RDS PostgreSQL Serverless,0.5-4RCU 50GB 3个月
推荐场景:
对影评进行热评分析
云数据库 RDS SQL Server,基础系列 2核4GB
RDS MySQL Serverless 基础系列,0.5-2RCU 50GB
简介:

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

相关实践学习
使用PolarDB和ECS搭建门户网站
本场景主要介绍基于PolarDB和ECS实现搭建门户网站。
阿里云数据库产品家族及特性
阿里云智能数据库产品团队一直致力于不断健全产品体系,提升产品性能,打磨产品功能,从而帮助客户实现更加极致的弹性能力、具备更强的扩展能力、并利用云设施进一步降低企业成本。以云原生+分布式为核心技术抓手,打造以自研的在线事务型(OLTP)数据库Polar DB和在线分析型(OLAP)数据库Analytic DB为代表的新一代企业级云原生数据库产品体系, 结合NoSQL数据库、数据库生态工具、云原生智能化数据库管控平台,为阿里巴巴经济体以及各个行业的企业客户和开发者提供从公共云到混合云再到私有云的完整解决方案,提供基于云基础设施进行数据从处理、到存储、再到计算与分析的一体化解决方案。本节课带你了解阿里云数据库产品家族及特性。
目录
相关文章
|
SQL 关系型数据库 MySQL
MySQL - 锁等待及死锁初探
MySQL - 锁等待及死锁初探
223 0
|
SQL 存储 Oracle
19 PostgreSQL 锁类型,锁模式,锁冲突,死锁检测的介绍|学习笔记
快速学习19 PostgreSQL 锁类型,锁模式,锁冲突,死锁检测的介绍
19 PostgreSQL 锁类型,锁模式,锁冲突,死锁检测的介绍|学习笔记
|
7月前
|
SQL 关系型数据库 MySQL
MySQL中锁等待超时与information_schema的三个表
MySQL中锁等待超时与information_schema的三个表
94 0
|
SQL 移动开发 关系型数据库
PostgreSQL 执行计划,成本公式解说,代价因子校准,自动跟踪SQL执行计划(三)|学习笔记
快速学习PostgreSQL 执行计划,成本公式解说,代价因子校准,自动跟踪SQL执行计划(三)
PostgreSQL 执行计划,成本公式解说,代价因子校准,自动跟踪SQL执行计划(三)|学习笔记
|
SQL 存储 缓存
23 PostgreSQL 监控4 动态内核跟踪 stap 篇|学习笔记
快速学习23 PostgreSQL 监控4 动态内核跟踪 stap 篇
23 PostgreSQL 监控4 动态内核跟踪 stap 篇|学习笔记
|
运维 关系型数据库 MySQL
MySQL锁等待与死锁问题分析
在 MySQL 运维过程中,锁等待和死锁问题是令各位 DBA 及开发同学非常头痛的事。出现此类问题会造成业务回滚、卡顿等故障,特别是业务繁忙的系统,出现死锁问题后影响会更严重。本篇文章我们一起来学习下什么是锁等待及死锁,出现此类问题又应该如何分析处理呢?
542 0
|
SQL 存储 关系型数据库
Mysql事物锁等待超时 Lock wait timeout exceeded; try restarting transaction
Mysql事物锁等待超时 Lock wait timeout exceeded; try restarting transaction
732 0
|
SQL 弹性计算 监控
PostgreSQL 谁堵塞了谁(锁等待检测)- pg_blocking_pids, pg_safe_snapshot_blocking_pids
标签 PostgreSQL , 锁等待 , 队列 背景 当一个进程处于等待(被堵塞)状态时,是谁干的?可以使用如下函数,快速得到捣蛋(堵塞别人)的PID。 1、请求锁时被堵,是哪些PID堵的? pg_blocking_pids(int) int[] Process ID(s) that are blocking specified server process ID from acq
1766 0
PostgreSQL 谁堵塞了谁(锁等待检测)- pg_blocking_pids, pg_safe_snapshot_blocking_pids
|
存储 SQL 关系型数据库
【学习资料】第16期快速入门PostgreSQL应用开发与管理 - 6 事务和锁
大家好,这里是快速入门PostgreSQL应用开发与管理 - 6 事务和锁
|
SQL 弹性计算 监控
PostgreSQL 谁堵塞了谁(锁等待检测)- pg_blocking_pids
标签 PostgreSQL , 锁等待 , 队列 背景 1 "被害人" 1、找到"被害人",获取被锁堵塞的PID select distinct pid from pg_locks where not granted; 2、找到"嫌疑人",获取被锁堵塞的PID是被哪些PID堵塞的 postgres=# select * from pg_blocking_pids(5392
1808 0

相关产品

  • 云原生数据库 PolarDB
  • 云数据库 RDS PostgreSQL 版