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

数据库 PostgreSQL
请注意,第一个计数,从存储中读取 1712 个 512 字节块,从内核缓存中读取 5 个 8kB 块到共享缓冲区缓存中。(未记录的读取数可能是系统表信息。)第二个查询显示没有来自存储设备的 I/O,并且在共享缓冲区中命中了 5 个 8kB 页面。

介绍

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

责任编辑:武晓燕 来源: 红石PG
相关推荐

2010-03-10 09:06:58

Windows 7启动时间

2010-01-26 08:58:17

Windows 7启动时间

2023-11-10 08:56:49

Springboot常用的注解

2023-09-14 10:42:46

SQL数据库

2020-09-27 09:41:04

代码开发注释

2009-11-24 18:20:16

曙光Gridview管理

2015-03-22 06:25:23

监控宝云智慧

2015-07-03 09:41:05

脚本编程编程语言比较

2021-01-12 16:28:41

5G运营商韩国

2012-04-25 09:17:41

Google DrivMicrosoft SDropbox

2023-10-07 09:34:03

数据可视化

2020-12-30 10:28:49

Windows 功能系统

2023-09-27 23:32:46

Python监控进程

2009-09-28 16:39:37

2014-08-21 11:12:01

QQ浏览器

2021-03-12 14:06:03

谷歌代码开发

2020-08-26 16:33:25

软件视频会议

2021-10-13 10:01:19

Windows 11操作系统微软

2020-04-17 15:03:28

动图Git命令
点赞
收藏

51CTO技术栈公众号