SET client_min_messages = log;
SET log_statement_stats = true;
SELECT 100;
LOG: QUERY STATISTICS
DETAIL: ! system usage stats:
1 ! 0.000000 s user, 0.000000 s system, 0.000201 s elapsed
2 ! [0.000000 s user, 0.000000 s system total]
3 ! 0/0 [0/0] filesystem blocks in/out
4 ! 0/14 [0/363] page faults/reclaims, 0 [0] swaps
5 ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
6 ! 0/0 [3/0] voluntary/involuntary context switches
?column?
----------
100
这些数字都意味着什么?其实,Linux 的 getrusage() 手册页中有一个线索:这些是内核资源使用情况的统计信息。前两行显示了用户层和内核层("system")使用的 CPU 时间,以及运行的时间。(第 #2 行及后面行的括号中的数字是,此过程的总数。第 #3 行显示了从/到存储设备(而不是内核缓存)的 I/O。第 #4 行涵盖了故障进入进程地址空间和回收的内存页。第 #5 行显示了信号和 IPC 消息的活动。第 #6 行显示了进程上下文切换。
示例
让我们通过填充一个新表,来查看一些更有趣的查询:
CREATE TABLE test (x INTEGER);
INSERT INTO test SELECT x FROM generate_series(1, 1000) t(x);
通过使用echo 3 > /proc/sys/vm/drop_caches清除内核缓冲区,并重新启动服务器,我们可以看到从存储设备(通过 log_statement_stats)和内核缓存(通过 explain (buffers true))的读取:
EXPLAIN (ANALYZE true, BUFFERS true, TIMING false, COSTS false)
SELECT COUNT(*) FROM test;
LOG: QUERY STATISTICS
DETAIL: ! system usage stats:
! 0.000000 s user, 0.000000 s system, 0.019259 s elapsed
! [0.008000 s user, 0.000000 s system total]
! 1712/0 [5840/280] filesystem blocks in/out
! 7/94 [21/586] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 29/1 [73/3] voluntary/involuntary context switches
QUERY PLAN
---------------------------------------------------
Aggregate (actual rows=1 loops=1)
Buffers: shared read=5
-> Seq Scan on test (actual rows=1000 loops=1)
Buffers: shared read=5
Planning time: 3.673 ms
Execution time: 2.221 ms
让我们再次运行查询:
EXPLAIN (ANALYZE true, BUFFERS true, TIMING false, COSTS false)
SELECT COUNT(*) FROM test;
LOG: QUERY STATISTICS
DETAIL: ! system usage stats:
! 0.000000 s user, 0.000000 s system, 0.000408 s elapsed
! [0.008000 s user, 0.000000 s system total]
! 0/0 [5840/288] filesystem blocks in/out
! 0/3 [21/591] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [74/3] voluntary/involuntary context switches
QUERY PLAN
---------------------------------------------------
Aggregate (actual rows=1 loops=1)
Buffers: shared hit=5
-> Seq Scan on test (actual rows=1000 loops=1)
Buffers: shared hit=5
Planning time: 0.027 ms
Execution time: 0.250 ms
请注意,第一个计数,从存储中读取 1712 个 512 字节块,从内核缓存中读取 5 个 8kB 块到共享缓冲区缓存中。(未记录的读取数可能是系统表信息。)第二个查询显示没有来自存储设备的 I/O,并且在共享缓冲区中命中了 5 个 8kB 页面。
总结
您可能有所了解,PostgreSQL 是分阶段执行查询的。幸运的是,您可以使用 log_parser_stats、log_planner_stats 和 log_executor_stats,获得每个阶段的 rusage 统计信息。(您可以在上面看到,explain (analyze true) 还显示了规划和执行的持续时间。)
如您所见,您可以访问到有关 PostgreSQL 的大量信息,以及它如何使用 CPU、存储和缓存。这些对查询的执行速度有很大影响。