PostgreSQL随机慢查询分析过程记录

王晓峰

软件工程师

摘要：

在PostgreSQL中，带子查询的复杂SQL语句，如果用LIMIT和OFFSET进行分页，有很大概率会出现慢查询。此时，需要采用规避措施（见正文规避措施一和规避措施二）。

先找了两篇文章做点技术储备：

PostgreSQL Running Slow? Tips & Tricks to Get to the Source

Debugging random slow writes in PostgreSQL

2021-06-08更新：

查询里有两个子查询，看起来是每个子查询会产生一个background worker，其中一个background worker在数据量不大不小的时候，会一直等待 DataFileRead，直到超时退出。

据说是和PostgreSQL处理的OFFSET的方式有关，如果没有OFFSET，查询很快就会返回结果，加了OFFSET，就会出现慢查询。找到了两个规避措施，一个是数据库每次都返回全部结果（最多几千条），在python程序里处理分页。一个是用func.row_number。

规避措施一：

total = len(records)
page_result = [records[i:i + size] for i in range(0, len(records), size)]
if page <= len(page_result):
    records = page_result[page - 1]
else:
    if total > 0:
        records = page_result[0]

规避措施二：

找到了在SQLAlchemy的query中使用row_number的方法：

filter by row_number in sqlalchemy

row_number_column = func.row_number().over(partition_by=Foo.foo_field, order_by=desc(Foo.foo_date_time)).label('row_number')
    query = self.session.query(Foo)
    query = query.filter(Foo.time_key <= time_key)
    query = query.add_column(row_number_column)
    query = query.from_self().filter(row_number_column == 1)

如果query自身带了排序，row_number_column也需要用同样的方式排序。

count(*)的方法：

How to count rows with SELECT COUNT(*) with SQLAlchemy?

session.query(MyModel).with_entities(func.count()).scalar()

StackOverFlow上有人建议不要用limit + offset做分页。

If PostgreSQL count(*) is always slow how to paginate complex queries?

Paginating using LIMIT and OFFSET is, IMO, an anti-pattern anyway. A lot of the time you can rephrase your pagination code so it uses sort_column > 'last_seen_value' LIMIT 100, i.e. it avoids the offset. This can sometimes result in very large performance gains.

--IMO ：可能是in my opinion的缩写

一、问题描述

Web上的一个功能，会偶然长时间无响应，看后端日志，是查询一直没返回结果。

一个多表关联查询，有一百多个字段，五张表关联，再加上两个子查询构造的临时表，开启了慢查询日志选项，所以在程序的日志中能找到完整的SQL语句和执行时用的参数。（记录下来的SQL语句需要手工替换参数，否则，在执行EXPLAIN时会提示语法错误。）

测试工程师找到了触发慢查询的方法：

选中系统中某个城市，再来运行Web上的功能，就有很高的概率出现慢查询。

城市信息对应系统中的两张很小的表，每张表有**条记录。

二、排除GIN索引的问题

上边提到的两篇文章，有一篇提到了GIN索引（random slow writes那篇），先看看用到的5张表有没有GIN日志。

创建GIN索引的SQL如下：

create index idx_ib_keywords on stuff using gin(to_tsvector('english'::regconfig, keywords));

可以从pg_indexes表找到创建index的语句：

select * from pg_indexes where tablename='*****'

可以看到都是btree索引，没用到GIN索引，排除GIN索引的问题

CREATE UNIQUE INDEX ***** ON public.***** USING btree (id)

另，为了确保没有gin索引，用如下语句又查了一下，确实没有带GIN的索引

select * from pg_indexes where indexdef like '%gin%'

三、EXPLAIN

替换参数

SQL语句中用到了date_part函数，经测试，可以这样替换：

select date_part('day', '2021-5-19 15:04:34.196531'::timestamp)

CASE WHEN (
    date_part(%(date_part_1)s, %(create_date_1)s - table_name.create_date) 
    < %(param_1)s) 
THEN date_part(%(date_part_1)s, %(create_date_1)s - table_name.create_date) 
ELSE %(param_2)s 
END AS sales_cycle

慢查询日志记录的参数：

'date_part_1': 'day', 
'create_date_1': datetime.datetime(2021, 5, 19, 15, 4, 34, 196531), 
'param_1': 20, 
'param_2': 20,

看到一个例子，可以在EXPLAIN后加上(ANALYZE,VERBOSE)

输出里面比较容易看到的是cost和actual time，cost的单位是磁盘页面数量，actual time的单位是毫秒，看起来慢查询的SQL语句本身并没有特别需要优化的地方。

四、检查表的状况

SELECT n_live_tup, n_dead_tup from pg_stat_user_tables where relname = 'table_name'

用这个SQL语句查了用到的5张表，都没有问题

五、查看postgresql的日志

在我们的服务器上，日志文件在

/var/log/postgresql目录下

日志文件会定期转储，可以用scp 命令把文件拷贝到工作PC上

2021-05-19 15:10:53.758 CST [****] ****@**** LOG:  could not receive data from client: Connection reset by peer

在慢查询日志时间附近的，只有这一条日志，看不到其他信息。

六、lock

下一个容易想到的原因就是锁了。

SQL语句执行时，在等待某个锁释放资源。

配置文件里有对应的配置项：

log_lock_waits -- 是否记录长时间等待锁的情况

deadlock_timeout -- 超过多长时间才记录

重新加载配置的方法：

Option 1: From the command-line shell

su - postgres
/usr/bin/pg_ctl reload

补充：可能需要指定配置文件的位置 -D /etc/postgresql/10/main

Option 2: Using SQL

SELECT pg_reload_conf();

七、重建两张小表的索引

在改配置的同时，还想到多年前遇到过的一个问题，Sybase 15.02刚发布的时候，我们在西班牙沃达丰用了这个版本，当时查询各种指标一直特别慢。按总部给的建议，当时分批重建各个大表的索引，一直没有效果，直到用户给的期限快到了，偶然更新了一张几十条记录的表的索引，查询效率才提高。

所以打算重建开篇提到的两张小表的索引。

重建索引的命令：

REINDEX TABLE my_table;

--六和七的效果待观察

2021-06-03 更新：

在测试服务器上打开了log_lock_waits开关

待观察结果

2021-06-04 更新：

修改配置项后，重新触发慢查询，日志里没出现相关内容。

那么应该不是在等待资源释放。

2021-06-07更新：

1、重建索引的办法无效

2、定时查询pg_stat_activity的shell

while [ "1" = "1" ]