ANBOB™

我们explain 增加analyze可以显示exection time实际执行所花的时间, 但是注意对于客户端执行SQL时的response time响应时间并不是这个exection time，这也是有时应用的人会反馈程序执行时间很慢，但我们在数据库端使用explain显示的exection time快，相差很大的原因。简单演示。

src/backend/commands/explain.c
/*
 * We only report execution time if we actually ran the query (that is,
 * the user specified ANALYZE), and if summary reporting is enabled (the
 * user can set SUMMARY OFF to not have the timing information included in
 * the output). By default, ANALYZE sets SUMMARY to true.
 */


src/backend/commands/explain.c

ExplainOnePlan()
	/*
	 * Close down the query and free resources.  Include time for this in the
	 * total execution time (although it should be pretty minimal).
	 */
	INSTR_TIME_SET_CURRENT(starttime);

	ExecutorEnd(queryDesc);

	FreeQueryDesc(queryDesc);

	PopActiveSnapshot();

	/* We need a CCI just in case query expanded to multiple plans */
	if (es->analyze)
		CommandCounterIncrement();

	totaltime += elapsed_time(&starttime);

	/*
	 * We only report execution time if we actually ran the query (that is,
	 * the user specified ANALYZE), and if summary reporting is enabled (the
	 * user can set SUMMARY OFF to not have the timing information included in
	 * the output).  By default, ANALYZE sets SUMMARY to true.
	 */
	if (es->summary && es->analyze)
		ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
							 es);

用一个例子演示

-- 使用的highgoDB v9

anbob=# create table test as select sysdate-x date,x id,100 amount from generate_series(1,100000) as x;
SELECT 100000

anbob=# explain analyze select * from (select distinct * from test) where id<10;
 QUERY PLAN
----------------------------------------------------------------------------------------------------------------
 Unique (cost=1791.17..1791.27 rows=10 width=16) (actual time=11.166..11.173 rows=9 loops=1)
 -> Sort (cost=1791.17..1791.19 rows=10 width=16) (actual time=11.164..11.166 rows=9 loops=1)
 Sort Key: test."date", test.id, test.amount
 Sort Method: quicksort Memory: 25kB
 -> Seq Scan on test (cost=0.00..1791.00 rows=10 width=16) (actual time=0.010..11.070 rows=9 loops=1)
 Filter: (id < 10)
 Rows Removed by Filter: 99991
 Planning Time: 0.157 ms
 Execution Time: 11.239 ms
(9 rows)

anbob=# explain analyze select * from (select distinct * from test) where rownum<=10;
                                                       QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
 Count StopKey  (cost=5755.84..6755.84 rows=0 width=16) (actual time=56.085..56.093 rows=10 loops=1)
   Filter: (rownum <= 10) ->  HashAggregate  (cost=5755.84..7732.41 rows=100000 width=16) (actual time=56.080..56.085 rows=11 loops=1)
         Group Key: test."date", test.id, test.amount
         Planned Partitions: 4  Batches: 5  Memory Usage: 4145kB  Disk Usage: 2824kB
         ->  Seq Scan on test  (cost=0.00..1541.00 rows=100000 width=16) (actual time=0.015..8.856 rows=100000 loops=1)
 Planning Time: 0.140 ms
 Execution Time: 57.051 ms
(8 rows)


anbob=> explain analyze SELECT * FROM test LIMIT 100;
                                                  QUERY PLAN
---------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.00..1.54 rows=100 width=16) (actual time=0.019..0.032 rows=100 loops=1)
   ->  Seq Scan on test  (cost=0.00..1541.00 rows=100000 width=16) (actual time=0.017..0.024 rows=100 loops=1)
 Planning Time: 0.275 ms
 Execution Time: 0.081 ms
(4 rows)

• Planning time When you run a query there is a lot of ways server can run this query. Query planner think and decide based on statistic of page. So Planning query is a time that query planner spend.
• Execution time is actual time server spend for execution this query.

看到Execution Time<Planning Time,  因为Execution Time不包含Planning Time.

我们把表数据增加，同时用一段简单的java代码模拟计算client返回行记录的时间

anbob=# insert into test select * from test;
INSERT 0 100000
anbob=# insert into test select * from test;
INSERT 0 200000
anbob=# insert into test select * from test;
INSERT 0 400000
anbob=# insert into test select * from test;
INSERT 0 800000
anbob=# insert into test select * from test;
INSERT 0 1600000

anbob=# select count(*)  from test;
  count
---------
 3200000

anbob=> explain analyze SELECT * FROM test;
                                                   QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..49298.00 rows=3200000 width=16) (actual time=0.009..291.796 rows=3200000 loops=1)
 Planning Time: 0.267 ms
 Execution Time: 410.090 ms
(3 rows)

$ export CLASSPATH=/data/highgo/app/drivers/jdbc/HgdbJdbc-9.0.1.jar:.
$ vi PostgreSQLQueryTimer.java
$ javac PostgreSQLQueryTimer.java
$ java PostgreSQLQueryTimer

▄︻デ══━ PostgreSQL查询结果 ══━─▄
│ 记录行数: 3200000行
│ 总耗时: 4255.968 毫秒
│ 平均每行: 1.330 微秒
▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔

Note:
注意Execution Time: 410ms, 但java 端执行用了4255ms, 相差10倍。 也是这java端总会大于Execution Time,因为客户端包含Execution Time，并额外增加了fetch data，传送数据到客户端，还有网络所花的时间。

The Execution time shown by EXPLAIN ANALYZE includes executor start-up and shut-down time, as well as the time to run any triggers that are fired, but it does not include parsing, rewriting, or planning time. Time spent executing BEFORE triggers, if any, is included in the time for the related Insert, Update, or Delete node; but time spent executing AFTER triggers is not counted there because AFTER triggers are fired after completion of the whole plan. The total time spent in each trigger (either BEFORE or AFTER) is also shown separately. Note that deferred constraint triggers will not be executed until end of transaction and are thus not considered at all by EXPLAIN ANALYZE.

The time shown for the top-level node does not include any time needed to convert the query’s output data into displayable form or to send it to the client. While EXPLAIN ANALYZE will never send the data to the client, it can be told to convert the query’s output data to displayable form and measure the time needed for that, by specifying the SERIALIZE option. That time will be shown separately, and it’s also included in the total Execution time.

简而言之，Execution time只是服务端执行器启动和结束的时间，不包含解析、重写或规划执行计划的时间，更不包含输出数据转换显示形式和发送到客户端所需的任何时间。

但是可以使用\timing on 在psql client显示fetch第一批的时间，也远大于execution时间.

anbob=> \timing on
Timing is on.
anbob=> select * from test;
       date        |   id   | amount
-------------------+--------+--------
 20250520 20:32:58 |      1 |    100
 20250519 20:32:58 |      2 |    100
 20250518 20:32:58 |      3 |    100
 20250517 20:32:58 |      4 |    100
 20250516 20:32:58 |      5 |    100
 20250515 20:32:58 |      6 |    100
 20250514 20:32:58 |      7 |    100
...
-- q   cancel 
Time: 3490.093 ms (00:03.490)
anbob=>

所以这里增加了网络传输的时间，那fetchsize也会影响client响应时间。 之前在oracleDB 记录过一个相关案例Oracle数据库中 Scalar-subquery 缓存和 DETERMINISTIC Function.

而应用中如果使用分页查询，而使用了cursor游标的话，也可以进行返回少数数据时快速返回的优化，默认情况下，游标会针对前 10% 的数据进行优化。即使设置 cursor_tuple_fraction 也可以更改此行为。

test=# BEGIN;
BEGIN
test=# SET cursor_tuple_fraction TO 0.0001;
SET

博客The power of response times and execution time记录了该技术点，不再复述。

上面java程序源码

 -- PostgreSQLQueryTimer.java
import java.sql.*;
import java.util.concurrent.TimeUnit;

public class PostgreSQLQueryTimer {
    // PostgreSQL连接配置（根据实际情况修改）
    private static final String DB_URL = "jdbc:postgresql://localhost:1521/anbob";
    private static final String USER = "anbob";
    private static final String PASS = "anbob";
    private static final String QUERY = "SELECT * FROM test";

    public static void main(String[] args) {
        Connection conn = null;
        PreparedStatement pstmt = null;

        try {
            // 1. 加载PostgreSQL JDBC驱动
            Class.forName("org.postgresql.Driver");

            // 2. 记录开始时间（包含连接建立时间）
            long startTime = System.nanoTime();

            // 3. 建立连接
            conn = DriverManager.getConnection(DB_URL, USER, PASS);

            // 4. 使用PreparedStatement（防止SQL注入）
            pstmt = conn.prepareStatement(QUERY);

            // 5. 执行查询
            ResultSet rs = pstmt.executeQuery();

            // 6. 遍历结果集（确保获取所有记录）
            int rowCount = 0;
            while (rs.next()) {
                rowCount++;
                // 实际应用中可在此处理每行数据
                // String value = rs.getString("column_name");
            }

            // 7. 计算耗时
            long endTime = System.nanoTime();
            long durationNano = endTime - startTime;
            double durationMs = durationNano / 1_000_000.0;

            System.out.println("▄︻デ══━ PostgreSQL查询结果 ══━─▄");
            System.out.println("│ 记录行数: " + rowCount + "行");
            System.out.printf("│ 总耗时: %.3f 毫秒%n", durationMs);
            System.out.printf("│ 平均每行: %.3f 微秒%n", (durationNano / 1000.0) / rowCount);
            System.out.println("▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔▔");

        } catch (ClassNotFoundException e) {
            System.err.println("PostgreSQL JDBC驱动未找到！");
            e.printStackTrace();
        } catch (SQLException e) {
            System.err.println("数据库连接/查询失败：");
            e.printStackTrace();
        } finally {
            // 8. 关闭资源（逆序关闭）
            try {
                if (pstmt != null) pstmt.close();
                if (conn != null) conn.close();
            } catch (SQLException e) {
                System.err.println("资源关闭异常：");
                e.printStackTrace();
            }
        }
    }
}

打赏

微信扫一扫，打赏作者吧～