今天有个库负载突然比较高，达到 50 左右，平常这个库是很空闲的，负载大部分时候都维持在1以下，于是查看数据库日志和当前活动会话，有个语句比较多，而且执行时间在 1.2s 左右, 于是单独分析这个 SQL， 奇怪的是，在数据库端执行这语句效率比较高，执行计划正确，索引也走对了，执行时间为零点几毫秒。于是怀疑这个语句的历史执行计划可能与当前的不一样；可 PostgreSQL 似乎没有提供系统 view 查询历史执行计划信息，网上查了下也没有结果，后来发现 auto_explain 模块可以记录SQL语句的执行计划到日志里，汗，虽然不是记录到系统表里，但总算也提供一种查询历史 PLAN 的方式。

Auto_explain 模块介绍

auto_explain 模块能够自动记录慢查询语句的执行计划，而不需要手工执行 Explain 命令，
在比较大的业务系统中，这个模块专门用来跟踪尚未优化的查询SQL。

Auto_explain 模块启用

如果已经编译并安装了 auto_explain 模块，只要配置参数 shared_preload_libraries , 和 custom_variable_classes 参数，如下所示。

postgresql.conf 配置以下参数：

1
2
3

shared_preload_libraries = 'auto_explain'  
custom_variable_classes = 'auto_explain'  
auto_explain.log_min_duration = '0'

1. auto_explain.log_min_duration 参数在配置文件里 PostgreSQL.conf 没有，需要手工添加，参数修改后，需要重启 PostgreSQL 服务。
2. 其中 auto_explain.log_min_duration 设置成了 0, 表示记录所有语句的PLAN，这是为了测试需要，在生产情况时，可以根据需求设置，一般设置成 1000ms。
3. auto_explain 的其它配置参数

• auto_explain.log_min_duration (integer)：这个参数用来控制执行时间在指定值以上的SQL的执行计划被记录。O 表示记录所有的语句的PLAN，默认什为 -1，表示不记录语句的PLAN。
• auto_explain.log_analyze (boolean)
• auto_explain.log_verbose (boolean)
• auto_explain.log_buffers (boolean)
• auto_explain.log_format (enum)
• auto_explain.log_nested_statements (boolean)

备注：这里主要介绍了参数 auto_explain.log_min_duration, 关于其它参数的用法可参考文档 http://www.postgresql.org/docs/9.0/static/auto-explain.html

Auto_explain 模块使用

创建测试表

1
2
3
4
5
6
7
8

skytf=> create table test_1 (id integer ,name varchar(32));  
CREATE TABLE  
  
skytf=> insert into test_1 select generate_series(1,100000) ,'francs';  
INSERT 0 100000

skytf=> create index idx_test_1_id on test_1 using btree (id);  
CREATE INDEX

测试一: session一执行查询

1
2
3
4
5

skytf=> select * from test_1 where id=1;  
id | name  
----+--------  
 1 | francs  
(1 row)

csvlog 日志记录了索引扫描信息

1
2
3
4

2011-08-09 13:17:12.250 CST,"skytf","skytf",10706,"127.0.0.1:54993",4e40aaf6.29d2,19,"SELECT",2011-08-09 11:35:18 CST,1/21,0,LOG,00000,"duration: 0.001 ms plan:  
Query Text: select * from test_1 where id=1;  
Index Scan using idx_test_1_id on test_1 (cost=0.00..8.28 rows=1 width=11)  
 Index Cond: (id = 1)",,,,,,,,,"psql"

备注：当SESSION一执行查询后，PG的日志里记录了语句的PLAN具体信息。

测试二: session一执行查询

1
2
3
4
5

skytf=> select count(*) from test_1 where id> 10;  
count  
-------  
99990  
(1 row)

csv日志记录了全表扫描信息

2011-08-09 13:19:18.094 CST,"skytf","skytf",10706,"127.0.0.1:54993",4e40aaf6.29d2,22,"SELECT",2011-08-09 11:35:18 CST,1/24,0,LOG,00000,"duration: 50.475 ms plan:  
Query Text: select count(*) from test_1 where id> 10;  
Aggregate (cost=1990.98..1990.99 rows=1 width=0)  
 -> Seq Scan on test_1 (cost=0.00..1741.00 rows=99991 width=0)  
 Filter: (id > 10)",,,,,,,,,"psql"

常见错误

在配置了参数 shared_preload_libraries = ‘auto_explain’后重启PG时，可能会报模块不存在等ERROR，这说明在编译PG时没有安装 auto_explain 模块，也就是在安装PG过程中需要使用 “gmake world” 进行编译，并且在安装时需要使用”gmake install-world”, 关于这方面的详细信可以参考文档，这里不做详细说明。

总结

由于PG没有系统视图可以查询语句的历史执行计划信息， 而 auto_explain 可以记录语句的历史PLAN，确实提供了一种不错的方法， 但在比较繁忙的业务系统中，如果开启这个模块，应该会稍微增加数据库压力，但不会太大。