PostgreSQL DBA(134) - Extension(auto_explain)

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

安装
编译安装

[pg12@localhost auto_explain]$ makemake -C ../../src/backend generated-headersmake[1]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend'make -C catalog distprep generated-header-symlinksmake[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-symlinksmake[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.Pogcc -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 installmake -C ../../src/backend generated-headersmake[1]: Entering directory `/home/pg12/source/postgresql-12.1/src/backend'make -C catalog distprep generated-header-symlinksmake[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-symlinksmake[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 restartwaiting for server to shut down.... doneserver stoppedwaiting 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-bit2019-11-20 16:32:21.013 CST [20847] LOG:  listening on IPv4 address "0.0.0.0", port 54322019-11-20 16:32:21.013 CST [20847] LOG:  listening on IPv6 address "::", port 54322019-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 process2019-11-20 16:32:21.088 CST [20847] HINT:  Future log output will appear in directory "pg_log". doneserver 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 reloadserver 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 = $1Index 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 = $1Index 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