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