PostgreSQL如何查找某一事务中的完整SQL

1,484 阅读15分钟
`

李振中,2020年8月加入去哪儿网,主要负责公司PostgreSQL和Oracle的运维管理工作。

1. 问题的提出

DBA 经常需要排查某一个事务中有哪些 SQL 的场景。典型的 case 就是 DB 有一个 lock 报警,从系统表中查看发现是1个 update 等待的 SQL 是1个 select。熟悉 PostgreSQL 的同学都知道:在 PostgreSQL 中,由于特有的 MVCC 机制,读不阻塞写,写不堵塞读。

那么为什么会产生这种 lock?

实际就是因为这个 select 处于一个事务中,事务中有其他 update/delete 等写入操作持有后面的其他事务中的 update 操作所需要的 lock。此时就需要到 DB log 去排查这个 select 所处的事务的完整的全部 SQL,反馈给业务线的开发同学,以便于进一步优化。

2. Log 相关参数

既然需要研究 DB log,先看看 log 的相关参数配置。

PostgreSQL 的 log 相关配置参数如下:

2.png 可见,PostgreSQL 的 log 相关配置参数非常丰富,本文限于篇幅不做展开讨论。

本文重点讨论几个生产中常用的参数 logging_collector ,log_min_duration_statement,log_statement,log_duration,log_line_prefix 。

2.1 logging_collector

设置为 on 才可记录 log 至文件,对此参数的更改需要重启生效。

2.2 log_min_duration_statement

可取值及含义如下:

取值含义
-1关闭
0记录所有的语句及其运行时间
>0仅记录超过此阈值的语句

2.3 log_statement

可选值有 none, ddl, mod, all。这个参数在 log_min_duration_statement >0 时决定记录到哪个级别的语句,在 log_min_duration_statement =0 时,不会影响是否记录全量 log。

2.4 log_duration

是否记录每个执行完成语句的时间。可取值为 on 或 off。

2.5 log_line_prefix

log_line_prefix 是一个 printf 风格的字符串,在日志的每行开头输出。其中各逃逸参数含义如下: 3.png

会话 ID 是每个会话的唯一标识符。它是两个 4 字节的十六进制数字(没有前导零),用句点分开。数值是会话开始时间和进程 ID ,因此也可以用做一种打印这些项目的节约空间的方法。

例如,想要从表 pgstatactivity 中生成一个会话的标识符,使用下面的查询语句:

SELECT to_hex(trunc(EXTRACT(EPOCH FROM backend_start))::integer) || '.' ||    
       to_hex(pid)
FROM pg_stat_activity;

记录的 log 是按照时间戳的前后进行的,一个事务里有很多操作语句,这样当多个并发事务并发执行,哪个statement 是哪个 pid/session 的,是哪个 virtual transaction 的,是哪个 transaction 的,如果不记录这些信息,我们就无从查起。

所以彻查某个问题需要详细查日志的时候,log_line_prefix 必须配置足够的参数。

定位事务中的 SQL,需要重点关注的是 %p %c %l %v %x。

3. log 配置 case

log_min_duration_statement,log_statement,log_duration 之间会相互影响。

由于篇幅所限,本文仅列举2个生产用常用的 case 看一下 DB log 的记录示例。

3.1 case 1 记录全量 log 模式

全量 log 模式 一般在需要调查问题的时候开启。

注意:全量 log 模式不仅有一种配置方式,现只列举其一。

参数配置如下:

postgres@localhost ~$ 
psql mydbpsql (12.3)
Type "help" for help.

mydb=# show logging_collector; 
 logging_collector
------------------- 
 on
 (1 row)
 
mydb=# show log_min_duration_statement; 
 log_min_duration_statement
----------------------------
 0
 (1 row)
 
mydb=#  show log_statement; 
 log_statement
--------------- 
 none
 (1 row)
 
postgres=# show log_duration; 
 log_duration
-------------- 
 off
 (1 row)
 
mydb=# show log_line_prefix;         
         log_line_prefix        
--------------------------------- 
 [%u %d %a %h %m %p %c %l %v %x]
 (1 row)

SQL 执行情况

postgres@localhost ~$ 
psql mydbpsql (12.3)
Type "help" for help.

mydb=# select pg_backend_pid(); 
 pg_backend_pid
 ----------------           
             7106
(1 row)

mydb=# begin;
BEGIN
mydb=# select 1; 
?column?
----------        
       1
(1 row)
mydb=# create table if not exists test(id int);
NOTICE:  relation "test" already exists, skipping
CREATE TABLE
mydb=# truncate table test;
TRUNCATE TABLE
mydb=# commit;
COMMIT
mydb=#
mydb=# begin;
BEGIN
mydb=# select * from test; 
 id
----
(0 rows)

mydb=# insert into test select 1;
INSERT 0 1
mydb=# insert into test select 2;
INSERT 0 1
mydb=# select * from test; 
 id----  
   1  
   2
 (2 rows)
 
mydb=# commit;
COMMIT
mydb=#
mydb=# begin;
BEGIN
mydb=# select 1; 
 ?column?
 ----------        
         1
(1 row)

mydb=# select * from test; 
 id
----  
  1
  2
(2 rows)

mydb=# update test set id = -1 where id =0;
UPDATE 0
mydb=# update test set id = -2 where id =1;
UPDATE 1
mydb=# select * from test; 
 id
----  
 2 
 -2
(2 rows)

mydb=# rollback;
ROLLBACK
mydb=#
mydb=# begin;
BEGIN
mydb=# update test set id = -1 where id =0;
UPDATE 0
mydb=# rollback;
ROLLBACK
mydb=#
mydb=# begin;
BEGIN
mydb=# update test set id = -2 where id =1;
UPDATE 1
mydb=# rollback;
ROLLBACK
mydb=#
mydb=# drop table if exists test;
DROP TABLE
mydb=#

DB log 记录情况

[postgres mydb psql [local] 2021-03-29 16:58:59.378 CST 7106 606196d2.1bc2 1 5/0 0]LOG:  duration: 0.770 ms  statement: select pg_backend_pid();

[postgres mydb psql [local] 2021-03-29 16:58:59.379 CST 7106 606196d2.1bc2 2 5/17 0]LOG:  duration: 0.057 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 16:58:59.380 CST 7106 606196d2.1bc2 3 5/17 0]LOG:  duration: 0.121 ms  statement: select 1;
[postgres mydb psql [local] 2021-03-29 16:58:59.386 CST 7106 606196d2.1bc2 4 5/17 0]LOG:  duration: 5.125 ms  statement: create table if not exists test(id int);
[postgres mydb psql [local] 2021-03-29 16:58:59.388 CST 7106 606196d2.1bc2 5 5/17 959]LOG:  duration: 1.112 ms  statement: truncate table test;
[postgres mydb psql [local] 2021-03-29 16:58:59.391 CST 7106 606196d2.1bc2 6 5/0 0]LOG:  duration: 1.916 ms  statement: commit;

[postgres mydb psql [local] 2021-03-29 16:58:59.392 CST 7106 606196d2.1bc2 7 5/18 0]LOG:  duration: 0.058 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 16:58:59.393 CST 7106 606196d2.1bc2 8 5/18 0]LOG:  duration: 0.548 ms  statement: select * from test;
[postgres mydb psql [local] 2021-03-29 16:58:59.395 CST 7106 606196d2.1bc2 9 5/18 960]LOG:  duration: 0.470 ms  statement: insert into test select 1;
[postgres mydb psql [local] 2021-03-29 16:58:59.396 CST 7106 606196d2.1bc2 10 5/18 960]LOG:  duration: 0.171 ms  statement: insert into test select 2;
[postgres mydb psql [local] 2021-03-29 16:58:59.397 CST 7106 606196d2.1bc2 11 5/18 960]LOG:  duration: 0.174 ms  statement: select * from test;
[postgres mydb psql [local] 2021-03-29 16:58:59.399 CST 7106 606196d2.1bc2 12 5/0 0]LOG:  duration: 1.194 ms  statement: commit;

[postgres mydb psql [local] 2021-03-29 16:58:59.400 CST 7106 606196d2.1bc2 13 5/19 0]LOG:  duration: 0.050 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 16:58:59.400 CST 7106 606196d2.1bc2 14 5/19 0]LOG:  duration: 0.222 ms  statement: select 1;
[postgres mydb psql [local] 2021-03-29 16:58:59.402 CST 7106 606196d2.1bc2 15 5/19 0]LOG:  duration: 0.197 ms  statement: select * from test;
[postgres mydb psql [local] 2021-03-29 16:58:59.404 CST 7106 606196d2.1bc2 16 5/19 0]LOG:  duration: 0.934 ms  statement: update test set id = -1 where id =0;
[postgres mydb psql [local] 2021-03-29 16:58:59.406 CST 7106 606196d2.1bc2 17 5/19 961]LOG:  duration: 0.310 ms  statement: update test set id = -2 where id =1;
[postgres mydb psql [local] 2021-03-29 16:58:59.407 CST 7106 606196d2.1bc2 18 5/19 961]LOG:  duration: 0.150 ms  statement: select * from test;
[postgres mydb psql [local] 2021-03-29 16:58:59.407 CST 7106 606196d2.1bc2 19 5/0 0]LOG:  duration: 0.062 ms  statement: rollback;

[postgres mydb psql [local] 2021-03-29 16:58:59.408 CST 7106 606196d2.1bc2 20 5/20 0]LOG:  duration: 0.036 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 16:58:59.410 CST 7106 606196d2.1bc2 21 5/20 0]LOG:  duration: 0.233 ms  statement: update test set id = -1 where id =0;
[postgres mydb psql [local] 2021-03-29 16:58:59.411 CST 7106 606196d2.1bc2 22 5/0 0]LOG:  duration: 0.053 ms  statement: rollback;

[postgres mydb psql [local] 2021-03-29 16:58:59.411 CST 7106 606196d2.1bc2 23 5/21 0]LOG:  duration: 0.032 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 16:58:59.413 CST 7106 606196d2.1bc2 24 5/21 962]LOG:  duration: 0.457 ms  statement: update test set id = -2 where id =1;
[postgres mydb psql [local] 2021-03-29 16:58:59.414 CST 7106 606196d2.1bc2 25 5/0 0]LOG:  duration: 0.076 ms  statement: rollback;

[postgres mydb psql [local2021-03-29 16:58:59.428 CST 7106 606196d2.1bc2 26 5/0 0]LOG:  duration: 12.573 ms  statement: drop table if exists test;

3.2 case 2 记录全量写&&部分读模式

记录全量写&&部分读是生产上最常用的 log 配置模式,配置方式更为灵活,同样也只列举其一。

参数配置如下:

postgres@localhost ~$ 
psqlpsql (12.3)
Type "help" for help. 

postgres=# show logging_collector ; 
 logging_collector
-------------------
 on
(1 row)

postgres=# show log_min_duration_statement ; 
 log_min_duration_statement
---------------------------- 
 1ms
(1 row) 

postgres=# show log_statement; 
 log_statement
--------------- 
 mod
(1 row) 

postgres=# show log_duration ; 
 log_duration
-------------- 
 off
(1 row) 

mydb=# show log_line_prefix ;         
         log_line_prefix        
--------------------------------- 
 [%u %d %a %h %m %p %c %l %v %x]
(1 row)

SQL 执行情况

postgres@localhost ~$ 
psql mydbpsql (12.3)
Type "help" for help. 

mydb=# select pg_backend_pid(); 
 pg_backend_pid
----------------           
           7234
(1 row) 

mydb=# begin;
BEGIN
mydb=# select 1; 
 ?column?
----------        
        1
(1 row) 

mydb=# create table if not exists test(id int);
CREATE TABLE
mydb=# truncate table test;
TRUNCATE TABLE
mydb=# commit;
COMMIT
mydb=#
mydb=# begin;
BEGIN
mydb=# select * from test; 
 id
----
(0 rows) 

mydb=# insert into test select 1;
INSERT 0 1
mydb=# insert into test select 2;
INSERT 0 1mydb=# select * from test; 
 id
----  
  1
  2
(2 rows) 

mydb=# commit;
COMMIT
mydb=#mydb=# begin;
BEGIN
mydb=# select 1; 
 ?column?
----------        
        1
(1 row)

mydb=# select * from test; 
 id
----
  1
  2
(2 rows) 

mydb=# update test set id = -1 where id =0;
UPDATE 0
mydb=# update test set id = -2 where id =1;
UPDATE 1
mydb=# select * from test; 
 id
----  
  2
  -2
(2 rows) 

mydb=# rollback;
ROLLBACK
mydb=#mydb=# begin;
BEGINmydb=# update test set id = -1 where id =0;
UPDATE 0
mydb=# rollback;
ROLLBACK
mydb=#mydb=# begin;
BEGIN
mydb=# update test set id = -2 where id =1;
UPDATE 1
mydb=# rollback;
ROLLBACK
mydb=#mydb=# drop table if exists test;
DROP TABLE

DB log 记录情况

[postgres mydb psql [local] 2021-03-29 17:05:21.188 CST 7234 60619844.1c42 1 3/521 0]LOG:  statement: create table if not exists test(id int);
[postgres mydb psql [local] 2021-03-29 17:05:21.208 CST 7234 60619844.1c42 2 3/521 964]LOG:  duration: 19.577 ms
[postgres mydb psql [local] 2021-03-29 17:05:21.209 CST 7234 60619844.1c42 3 3/521 964]LOG:  statement: truncate table test;
[postgres mydb psql [local] 2021-03-29 17:05:21.212 CST 7234 60619844.1c42 4 3/0 0]LOG:  duration: 2.575 ms  statement: commit;

[postgres mydb psql [local] 2021-03-29 17:05:21.216 CST 7234 60619844.1c42 5 3/522 0]LOG:  statement: insert into test select 1;
[postgres mydb psql [local] 2021-03-29 17:05:21.217 CST 7234 60619844.1c42 6 3/522 965]LOG:  statement: insert into test select 2;
[postgres mydb psql [local] 2021-03-29 17:05:21.221 CST 7234 60619844.1c42 7 3/0 0]LOG:  duration: 1.439 ms  statement: commit; 

[postgres mydb psql [local] 2021-03-29 17:05:21.226 CST 7234 60619844.1c42 8 3/523 0]LOG:  statement: update test set id = -1 where id =0;
[postgres mydb psql [local] 2021-03-29 17:05:21.228 CST 7234 60619844.1c42 9 3/523 0]LOG:  statement: update test set id = -2 where id =1; 

[postgres mydb psql [local] 2021-03-29 17:05:21.233 CST 7234 60619844.1c42 10 3/524 0]LOG:  statement: update test set id = -1 where id =0; 

[postgres mydb psql [local] 2021-03-29 17:05:21.235 CST 7234 60619844.1c42 11 3/525 0]LOG:  statement: update test set id = -2 where id =1; 

[postgres mydb psql [local] 2021-03-29 17:05:21.237 CST 7234 60619844.1c42 12 3/526 0]LOG:  statement: drop table if exists test;
[postgres mydb psql [local] 2021-03-29 17:05:21.240 CST 7234 60619844.1c42 13 3/0 0]LOG:  duration: 2.545 ms

4. 小结

由上述 case 可见,不同设置值的组合,以及不同的 SQL 语句(DML,DDL,DCL)类型,均影响着 log 文件中的记录的最终内容及格式。

在 PostgreSQL 的 DB log 中,现直接给出几个基本结论:

  1. %p和%c,即进程 ID 和会话 ID 是一一对应的,但明显会话 ID 在大量 log 中比数字形式的进程 ID 更具有特异性;
  2. 事务开始的 BEGIN 即分配%v,即虚拟事务 ID (backendID/localXID) ,且 COMMIT/ROLLBACK 的 localXID 为0;但 BEGIN/COMMIT/ROLLBACK 的事务 ID 为0;
  3. 同一个事务中,%v,即虚拟事务 ID (backendID/localXID)是一致的,可以作为查找同一事务中完整 SQL(或者说 statement)的依据;
  4. 同一个事务中,%x,即事务 ID 的情况比较复杂,
  • 事务中的第一条 SQL 如果是 select 或不产生真正写入的 DML,则打印的事务 ID 永远是0,
  • 事务中的第一条 SQL 即使是产生真正写入的 DML 及 DDL 也不一定打印事务 ID(虽然 PostgreSQL 内部此时已分配了事务 ID),
  • 所以事务 ID 不可作为查找同一事务中完整 SQL 的依据,可作为辅助信息;

   5.  一旦非0事务号出现,后续事务中任何 SQL 的 transaction id 均保持一致;

5. 具体实例

根据上述示例和结论,我们看一个 DB lock 需要查看事务中完整 SQL 的实例。

Seesion A:

mydb=# begin;
BEGIN
mydb=# update test set id = 0
mydb-# where id =1;
UPDATE 1
mydb=# select txid_current_if_assigned(); 
 txid_current_if_assigned
--------------------------                      
                      954
(1 row) 
 mydb=# select id from test; 
 id
---- 
  2
  0
(2 rows)

Session B:

mydb=# select pg_backend_pid(); 
 pg_backend_pid
----------------           
           5703
(1 row) 

mydb=# update test set id = -1 where id =1; 

--此时Session B的update 处于waiting 状态

Session C:

--查询lock情况的SQL由于过长,此处省略 

-[ RECORD 1 ]------------+-------------------------------------
pid                      | 5703
state                    | active
transactionid            | 956
virtualxid               |
locktype                 | transactionid
usename                  | postgres
application_name         | psql
client_addr              |
wait_event_type          | Lock
wait_event               | transactionid
query_start              | 2021-03-29 15:54:20.126504+08
query_runtime            | 115.839947
query                    | update test set id = -1 where id =1;
relation                 |
relname                  |
waitfor_relation         |
waitfor_pid              | 5665
waitfor_state            | idle in transaction
waitfor_transactionid    | 954
waitfor_virtualxid       |
waitfor_locktype         | transactionid
waitfor_usename          | postgres
waitfor_client_addr      |
waitfor_application_name | psql
waitfor_wait_event_type  | Client
waitfor_wait_event       | ClientRead
waitfor_query_start      | 2021-03-29 15:53:01.613482+08
waitfor_query_runtime    | 194.352969
waitfor_query            | select id from test;

为了便于演示,假定该 DB 实例已开启全量 log 模式。

现详细看一下 DB log 查找完整 SQL 过程:

  1. 定位 log 文件 在 DB log 目录中先大致找到 query_start 在 2021-03-29 15:53:01 的所在的 log 文件。
postgres@localhost log$ ll postgresql-2021-03-29*log
-rw------- 1 postgres postgres 19405 329 16:00 postgresql-2021-03-29_142024.log

由于本机 log 量很少,所以可直接定位在此唯一文件中。生产环境中,尤其是 qps 高的实例,需要仔细一点来缩小范围。

  1. 根据 pid 继续定位

可以看到等待的事务对应的 pid 为5665

postgres@localhost log$ grep 5665 postgresql-2021-03-29_142024.log
[postgres mydb psql [local] 2021-03-29 15:47:35.859 CST 5665 6061856f.1621 1 3/0 0]LOG:  duration: 4.909 ms  statement: select pg_backend_pid();
[postgres mydb psql [local] 2021-03-29 15:47:45.398 CST 5665 6061856f.1621 2 3/0 0]LOG:  duration: 8.214 ms  statement: select id from test;
[postgres mydb psql [local] 2021-03-29 15:47:52.950 CST 5665 6061856f.1621 3 3/0 0]LOG:  duration: 8.431 ms  statement: truncate table test;
[postgres mydb psql [local] 2021-03-29 15:48:07.668 CST 5665 6061856f.1621 4 3/0 0]LOG:  duration: 5.687 ms  statement: insert into test select 1;
[postgres mydb psql [local] 2021-03-29 15:48:14.163 CST 5665 6061856f.1621 5 3/0 0]LOG:  duration: 5.082 ms  statement: insert into test select 2;
[postgres mydb psql [local] 2021-03-29 15:49:03.791 CST 5735 606185ab.1667 1 5/0 0]LOG:  duration: 1.091 ms  statement: select 5665 + 1;
[postgres mydb psql [local] 2021-03-29 15:49:07.518 CST 5735 606185ab.1667 2 5/0 0]LOG:  duration: 0.356 ms  statement: select 5665 - 1;
[postgres mydb psql [local] 2021-03-29 15:49:38.542 CST 5735 606185ab.1667 3 5/0 0]LOG:  duration: 0.196 ms  statement: select 56650 - 56650;
[postgres mydb psql [local] 2021-03-29 15:51:45.950 CST 5665 6061856f.1621 6 3/0 0]LOG:  duration: 0.360 ms  statement: select txid_current_if_assigned();
[postgres mydb psql [local] 2021-03-29 15:51:48.958 CST 5665 6061856f.1621 7 3/516 0]LOG:  duration: 0.061 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 15:52:09.311 CST 5665 6061856f.1621 8 3/516 954]LOG:  duration: 1.646 ms  statement: update test set id = 0
[postgres mydb psql [local] 2021-03-29 15:52:12.030 CST 5665 6061856f.1621 9 3/516 954]LOG:  duration: 0.181 ms  statement: select txid_current_if_assigned();
[postgres mydb psql [local2021-03-29 15:53:01.613 CST 5665 6061856f.1621 10 3/516 954]LOG:  duration: 0.213 ms  statement: select id from test;
  1. 根据 session id 进一步定位

可以看到 pid 31720对应的 session 为 6061856f.1621,再结合 statement 及 waitforquerystart 的时间进一步具体排除干扰项。

postgres@localhost log$ grep ' 6061856f.1621 ' postgresql-2021-03-29_142024.log | grep 'select id from test'
[postgres mydb psql [local] 2021-03-29 15:47:45.398 CST 5665 6061856f.1621 2 3/0 0]LOG:  duration: 8.214 ms  statement: select id from test;
[postgres mydb psql [local] 2021-03-29 15:53:01.613 CST 5665 6061856f.1621 10 3/516 954]LOG:  duration: 0.213 ms  statement: select id from test; 

postgres@localhost log$ grep ' 6061856f.1621 ' postgresql-2021-03-29_142024.log | grep 'select id from test' | grep '2021-03-29 15:53'
[postgres mydb psql [local2021-03-29 15:53:01.613 CST 5665 6061856f.1621 10 3/516 954]LOG:  duration: 0.213 ms  statement: select id from test;
  1. 根据 virtualxid 进一步定位

可以看到 virtualxid 为 3/516

postgres@localhost log$ grep ' 6061856f.1621 ' postgresql-2021-03-29_142024.log | grep '3/516'
[postgres mydb psql [local] 2021-03-29 15:51:48.958 CST 5665 6061856f.1621 7 3/516 0]LOG:  duration: 0.061 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 15:52:09.311 CST 5665 6061856f.1621 8 3/516 954]LOG:  duration: 1.646 ms  statement: update test set id = 0
[postgres mydb psql [local] 2021-03-29 15:52:12.030 CST 5665 6061856f.1621 9 3/516 954]LOG:  duration: 0.181 ms  statement: select txid_current_if_assigned();
[postgres mydb psql [local2021-03-29 15:53:01.613 CST 5665 6061856f.1621 10 3/516 954]LOG:  duration: 0.213 ms  statement: select id from test;
  1. 处理折行

特别注意:有些 SQL 带有回车/换行(比如 statement: update test set id = 0 明显没有代表命令结束符的分号),DB log 中记录为 tab 键。有很多方式可以处理这种情况,此处使用一个 perl 来搞定。

postgres@localhost log$ cat postgresql-2021-03-29_142024.log | perl -e 'while(<>){ if($_ !~ /^\t/ig) { chomp; print "\n",$_;} else {chomp; print;}}' | grep ' 6061856f.1621 ' | grep '3/516'
[postgres mydb psql [local] 2021-03-29 15:51:48.958 CST 5665 6061856f.1621 7 3/516 0]LOG:  duration: 0.061 ms  statement: begin;
[postgres mydb psql [local] 2021-03-29 15:52:09.311 CST 5665 6061856f.1621 8 3/516 954]LOG:  duration: 1.646 ms  statement: update test set id = 0    where id =1;
[postgres mydb psql [local] 2021-03-29 15:52:12.030 CST 5665 6061856f.1621 9 3/516 954]LOG:  duration: 0.181 ms  statement: select txid_current_if_assigned();
[postgres mydb psql [local] 2021-03-29 15:53:01.613 CST 5665 6061856f.1621 10 3/516 954]LOG:  duration: 0.213 ms  statement: select id from test;

可见,通过连续的行号(7 至 10)辅助来看,中间没有丢任何 log;至此,DB lock 中进程5665阻塞进程5703的完整事务已经全部定位。\

实际生产环境中,尤其 qps 高,并发读写量大的 DB 实例中,情况远比这个实例复杂,且大部分情况下,log 模式为 记录全量写&&记录部分读,所以定位难度会增大。

此时可继续结合 log_line_prefix 的其他逃逸参数,比如%u,%a,%h等。

同时也可开启其他参数来辅助定位。比如此时我们设置 log_lock_waits 为 on,然后 cancel 掉进程5703的 update,再次执行同一 update,超过 deadlock_timeout (默认为1s)后,进程5703就会在 DB log 中打印如下信息:

[postgres mydb psql [local] 2021-03-29 15:54:11.789 CST 5703 60618581.1647 1 4/0 0]LOG:  duration: 0.297 ms  statement: select pg_backend_pid();
[postgres mydb psql [local] 2021-03-29 16:17:28.272 CST 5703 60618581.1647 2 4/11 956]ERROR:  canceling statement due to user request
[postgres mydb psql [local] 2021-03-29 16:17:28.272 CST 5703 60618581.1647 3 4/11 956]CONTEXT:  while updating tuple (0,1) in relation "test"
[postgres mydb psql [local] 2021-03-29 16:17:28.272 CST 5703 60618581.1647 4 4/11 956]STATEMENT:  update test set id = -1 where id =1;
[postgres mydb psql [local] 2021-03-29 16:17:31.545 CST 5703 60618581.1647 5 4/12 957]LOG:  process 5703 still waiting for ShareLock on transaction 954 after 1000.199 ms
[postgres mydb psql [local] 2021-03-29 16:17:31.545 CST 5703 60618581.1647 6 4/12 957]DETAIL:  Process holding the lock: 5665. Wait queue: 5703.
[postgres mydb psql [local] 2021-03-29 16:17:31.545 CST 5703 60618581.1647 7 4/12 957]CONTEXT:  while updating tuple (0,1) in relation "test"
[postgres mydb psql [local] 2021-03-29 16:17:31.545 CST 5703 60618581.1647 8 4/12 957]STATEMENT:  update test set id = -1 where id =1;

6 综述

查找某一事务中的完整 SQL 是一个慢工细活,考察 DBA 的诸多细节知识储备,同时考验 DBA 的耐心,但确实是非常实用的 DBA 必备运维技能。

本文从运维实践的角度浅析了一下,欢迎大家来从底层原理/源码的角度探讨更高效的结论和方法。