PostgreSQL 的 Trace 日志，查询的内核资源消耗一目了然！

介绍

PostgreSQL 包含了许多监控工具，可让您查看正在发生的事情，但有一些设置的确会看到很详细的信息，比如 log_statement_stats：

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、存储和缓存。这些对查询的执行速度有很大影响。