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

关注

发布于: 2021 年 08 月 02 日

李振中，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 相关配置参数如下：

可见，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

可取值及含义如下：

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 风格的字符串，在日志的每行开头输出。其中各逃逸参数含义如下：

会话 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;BEGINmydb=# select 1; ?column?----------        1(1 row)
mydb=# create table if not exists test(id int);NOTICE:  relation "test" already exists, skippingCREATE TABLEmydb=# truncate table test;TRUNCATE TABLEmydb=# commit;COMMITmydb=#mydb=# begin;BEGINmydb=# select * from test; id----(0 rows)
mydb=# insert into test select 1;INSERT 0 1mydb=# insert into test select 2;INSERT 0 1mydb=# select * from test; id----  1  2(2 rows)
mydb=# commit;COMMITmydb=#mydb=# begin;BEGINmydb=# 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 0mydb=# update test set id = -2 where id =1;UPDATE 1mydb=# select * from test; id----  2 -2(2 rows)
mydb=# rollback;ROLLBACKmydb=#mydb=# begin;BEGINmydb=# update test set id = -1 where id =0;UPDATE 0mydb=# rollback;ROLLBACKmydb=#mydb=# begin;BEGINmydb=# update test set id = -2 where id =1;UPDATE 1mydb=# rollback;ROLLBACKmydb=#mydb=# drop table if exists test;DROP TABLEmydb=#

复制代码

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 [local] 2021-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;BEGINmydb=# select 1; ?column?----------        1(1 row) mydb=# create table if not exists test(id int);CREATE TABLEmydb=# truncate table test;TRUNCATE TABLEmydb=# commit;COMMITmydb=#mydb=# begin;BEGINmydb=# select * from test; id----(0 rows) mydb=# insert into test select 1;INSERT 0 1mydb=# insert into test select 2;INSERT 0 1mydb=# select * from test; id----  1  2(2 rows) mydb=# commit;COMMITmydb=#mydb=# begin;BEGINmydb=# 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 0mydb=# update test set id = -2 where id =1;UPDATE 1mydb=# select * from test; id----  2 -2(2 rows) mydb=# rollback;ROLLBACKmydb=#mydb=# begin;BEGINmydb=# update test set id = -1 where id =0;UPDATE 0mydb=# rollback;ROLLBACKmydb=#mydb=# begin;BEGINmydb=# update test set id = -2 where id =1;UPDATE 1mydb=# rollback;ROLLBACKmydb=#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 中，现直接给出几个基本结论：

%p 和 %c，即进程 ID 和会话 ID 是一一对应的，但明显会话 ID 在大量 log 中比数字形式的进程 ID 更具有特异性；
事务开始的 BEGIN 即分配 %v，即虚拟事务 ID (backendID/localXID) ，且 COMMIT/ROLLBACK 的 localXID 为 0；但 BEGIN/COMMIT/ROLLBACK 的事务 ID 为 0；
同一个事务中，%v，即虚拟事务 ID (backendID/localXID)是一致的，可以作为查找同一事务中完整 SQL(或者说 statement)的依据；
同一个事务中，%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;BEGINmydb=# update test set id = 0mydb-# where id =1;UPDATE 1mydb=# 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                      | 5703state                    | activetransactionid            | 956virtualxid               |locktype                 | transactionidusename                  | postgresapplication_name         | psqlclient_addr              |wait_event_type          | Lockwait_event               | transactionidquery_start              | 2021-03-29 15:54:20.126504+08query_runtime            | 115.839947query                    | update test set id = -1 where id =1;relation                 |relname                  |waitfor_relation         |waitfor_pid              | 5665waitfor_state            | idle in transactionwaitfor_transactionid    | 954waitfor_virtualxid       |waitfor_locktype         | transactionidwaitfor_usename          | postgreswaitfor_client_addr      |waitfor_application_name | psqlwaitfor_wait_event_type  | Clientwaitfor_wait_event       | ClientReadwaitfor_query_start      | 2021-03-29 15:53:01.613482+08waitfor_query_runtime    | 194.352969waitfor_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 3月  29 16:00 postgresql-2021-03-29_142024.log

复制代码

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

2、根据 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 [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;

复制代码

3、根据 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 [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;

复制代码

4、根据 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 [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;

复制代码

5、处理折行

特别注意：有些 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 必备运维技能。

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

发布于: 2021 年 08 月 02 日阅读数: 13

原文链接:【http://xie.infoq.cn/article/22d474df4ca308626277b80d5】。未经作者许可，禁止转载。

Qunar技术沙龙

关注

还未添加个人签名 2020.11.28 加入

还未添加个人简介

发布

暂无评论

创作场景

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

1. 问题的指出

2. Log 相关参数

2.1 logging_collector

2.2 log_min_duration_statement

2.3 log_statement

2.4 log_duration

2.5 log_line_prefix

3. Log 配置 Case

3.1 case 1 记录全量 log 模式

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

4. 小结

5. 具体实例

6 综述

Qunar技术沙龙

评论