PostgreSQL DBA(134) - Extension(auto_explain)

本文简单介绍了PostgreSQL的插件：auto_explain。该插件自动explain SQL语句并把执行计划打印在日志文件中。

安装
编译安装

 [pg12@localhost auto_explain]$ make make -C ../../src/backend generated-headers make[1]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend' make -C catalog distprep generated-header-symlinks make[2]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend/catalog' make[2]: Nothing to be done for `distprep'. make[2]: Nothing to be done for `generated-header-symlinks'. make[2]: Leaving directory `/home/pg12/source/postgresql-12.1/src/backend/catalog' make -C utils distprep generated-header-symlinks make[2]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend/utils' make[2]: Nothing to be done for `distprep'. make[2]: Nothing to be done for `generated-header-symlinks'. make[2]: Leaving directory `/home/pg12/source/postgresql-12.1/src/backend/utils' make[1]: Leaving directory `/home/pg12/source/postgresql-12.1/src/backend' gcc -std=gnu99 -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Werror=vla -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard -g -O0 -DOPTIMIZER_DEBUG -g3 -gdwarf-2 -fPIC -I. -I. -I../../src/include -D_GNU_SOURCE -I/usr/include/libxml2 -c -o auto_explain.o auto_explain.c -MMD -MP -MF .deps/auto_explain.Po gcc -std=gnu99 -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Werror=vla -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard -g -O0 -DOPTIMIZER_DEBUG -g3 -gdwarf-2 -fPIC -shared -o auto_explain.so auto_explain.o -L../../src/port -L../../src/common -Wl,--as-needed -Wl,-rpath,'/appdb/pg12/pg12.1/lib',--enable-new-dtags [pg12@localhost auto_explain]$ make install make -C ../../src/backend generated-headers make[1]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend' make -C catalog distprep generated-header-symlinks make[2]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend/catalog' make[2]: Nothing to be done for `distprep'. make[2]: Nothing to be done for `generated-header-symlinks'. make[2]: Leaving directory `/home/pg12/source/postgresql-12.1/src/backend/catalog' make -C utils distprep generated-header-symlinks make[2]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend/utils' make[2]: Nothing to be done for `distprep'. make[2]: Nothing to be done for `generated-header-symlinks'. make[2]: Leaving directory `/home/pg12/source/postgresql-12.1/src/backend/utils' make[1]: Leaving directory `/home/pg12/source/postgresql-12.1/src/backend' /bin/mkdir -p '/appdb/pg12/pg12.1/lib/postgresql' /bin/install -c -m 755 auto_explain.so '/appdb/pg12/pg12.1/lib/postgresql/auto_explain.so' 

体验
修改配置文件，重启数据库

 [pg12@localhost pg121db]$ cat postgresql.auto.conf # Do not edit this file manually! # It will be overwritten by the ALTER SYSTEM command. shared_preload_libraries = 'auto_explain,anon' [pg12@localhost pg121db]$ [pg12@localhost auto_explain]$ pg_ctl restart waiting for server to shut down.... done server stopped waiting for server to start....2019-11-20 16:32:21.013 CST [20847] LOG: starting PostgreSQL 12.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-16), 64-bit 2019-11-20 16:32:21.013 CST [20847] LOG: listening on IPv4 address "0.0.0.0", port 5432 2019-11-20 16:32:21.013 CST [20847] LOG: listening on IPv6 address "::", port 5432 2019-11-20 16:32:21.015 CST [20847] LOG: listening on Unix socket "/data/pg12/.s.PGSQL.5432" 2019-11-20 16:32:21.088 CST [20847] LOG: redirecting log output to logging collector process 2019-11-20 16:32:21.088 CST [20847] HINT: Future log output will appear in directory "pg_log". done server started [pg12@localhost auto_explain]$ 

设置auto_explain参数，并加载参数

 [local:/data/pg12]:5432 pg12@testdb=# alter system set auto_explain.log_min_duration = 0; ALTER SYSTEM [local:/data/pg12]:5432 pg12@testdb=# alter system set auto_explain.log_analyze = on; ALTER SYSTEM [local:/data/pg12]:5432 pg12@testdb=# ... [pg12@localhost pg121db]$ pg_ctl reload server signaled [pg12@localhost pg121db]$ 

在psql中执行查询，检查日志输出

 [local:/data/pg12]:5432 pg12@testdb=# select * from tbl; id ---- (0 rows) [local:/data/pg12]:5432 pg12@testdb=# 2019-11-20 16:35:34.480 CST,"pg12","testdb",20869,"[local]",5dd4fa24.5185,62,"SELECT",2019-11-20 16:32:36 CST,3/8,0,LOG,00000,"duration: 0.019 ms plan: Query Text: select * from tbl; Seq Scan on tbl (cost=0.00..35.50 rows=2550 width=4) (actual time=0.009..0.009 rows=0 loops=1)",,,,,,,,,"psql" --------------------------------- [local:/data/pg12]:5432 pg12@testdb=# select * from tbl where id = 100::float; id ----- 100 (1 row) [local:/data/pg12]:5432 pg12@testdb=# 2019-11-20 16:54:08.280 CST,"pg12","testdb",21506,"[local]",5dd4fcf2.5402,2,"SELECT",2019-11-20 16:44:34 CST,3/5,0,LOG,00000,"duration: 38.947 ms plan: Query Text: select * from tbl where id = 100::float; Seq Scan on tbl (cost=0.00..1943.00 rows=500 width=4) (actual time=0.135..38.925 rows=1 loops=1) Filter: ((id)::double precision = '100'::double precision) Rows Removed by Filter: 99999",,,,,,,,,"psql" 

使用JDBC程序测试

  /* * */ package testPG; import java.sql.Connection; import java.sql.DriverManager; import java.sql.PreparedStatement; import java.sql.ResultSet; import java.sql.SQLException; public class TestAutoExplain { public static void main(String[] args) { try (Connection conn = DriverManager.getConnection("jdbc:postgresql://192.168.26.28:5432/testdb", "pg12", "root")) { TestExplicitType(conn); TestImplicitType(conn); } catch (SQLException se) { System.out.println(se.getMessage()); } catch (Exception e) { e.printStackTrace(); } finally { } // end try } public static void TestExplicitType(Connection conn) { try (PreparedStatement pstmt = conn.prepareStatement("SELECT id from tbl where id = ?");) { conn.setAutoCommit(true); pstmt.setInt(1, 100); try (ResultSet rs = pstmt.executeQuery()) { if (rs.next()) { int id = rs.getInt("id"); System.out.println("id:" + id); } } } catch (SQLException se) { System.out.println(se.getMessage()); } catch (Exception e) { e.printStackTrace(); } finally { } // end try } // end public static void TestImplicitType(Connection conn) { try (PreparedStatement pstmt = conn.prepareStatement("SELECT id from tbl where id = ?");) { conn.setAutoCommit(true); pstmt.setObject(1, 100); try (ResultSet rs = pstmt.executeQuery()) { if (rs.next()) { int id = rs.getInt("id"); System.out.println("id:" + id); } } } catch (SQLException se) { System.out.println(se.getMessage()); } catch (Exception e) { e.printStackTrace(); } finally { } // end try } // end } // end Class 

数据库后台日志输出

 2019-11-20 16:45:55.349 CST,"pg12","testdb",21581,"192.168.119.33:54001",5dd4fd43.544d,1,"SELECT",2019-11-20 16:45:55 CST,4/22,0,LOG,00000,"duration: 28.367 ms plan: Query Text: SELECT id from tbl where id = $1 Index Only Scan using idx_tbl_id on tbl (cost=0.29..8.31 rows=1 width=4) (actual time=28.301..28.311 rows=1 loops=1) Index Cond: (id = 100) Heap Fetches: 1",,,,,,,,,"PostgreSQL JDBC Driver" 2019-11-20 16:45:55.365 CST,"pg12","testdb",21581,"192.168.119.33:54001",5dd4fd43.544d,2,"SELECT",2019-11-20 16:45:55 CST,4/23,0,LOG,00000,"duration: 0.080 ms plan: Query Text: SELECT id from tbl where id = $1 Index Only Scan using idx_tbl_id on tbl (cost=0.29..8.31 rows=1 width=4) (actual time=0.064..0.067 rows=1 loops=1) Index Cond: (id = 100) Heap Fetches: 1",,,,,,,,,"PostgreSQL JDBC Driver" 

虽然使用setObject作为参数设定，但驱动正确设置了参数类型为int，并没有出现double -> int的转换。

参考资料
Making Mystery-Solving Easier with auto_explain