深入浅出 bpftrace 分析 PostgreSQL
本页目录
前言
很早之前就想写一篇关于 bpftrace 分析 PostgreSQL 的文章了。
原因也很简单，日常排查 PostgreSQL 问题时，我们已经习惯了先看 pg_stat_activity、pg_stat_statements、pg_locks，再结合数据库日志、操作系统指标综合分析。大多数问题到这里基本就能有个眉目。
但是总有一些场景，让人看得云里雾里：
pg_stat_statements里 SQL 很慢，但慢在 CPU、锁、IO，还是系统调用？- 明明
shared_blks_read很高，但到底有没有真正落到内核 IO？ wait_event看到 LWLock，但到底卡在什么路径上？- 临时文件写了不少，但系统调用层面读写了多少？
- PostgreSQL 自己的统计视图看不到的东西，还有没有办法继续往下挖？
这时候 bpftrace 就很有意思了。
它不是替代 PostgreSQL 视图的工具，而是帮我们把观察范围从 PostgreSQL 内部继续往下打穿，打到系统调用、内核 tracepoint、用户态 USDT 探针，甚至函数调用栈。
以前看 Andres Freund、Dmitrii Dolgov 关于 perf/eBPF/bpftrace 的分享，觉得思路非常漂亮，但光看材料总有种“隔靴搔痒”的感觉。于是这次我专门准备了一台 Rocky Linux 9.5 云主机，把 PostgreSQL、bpftrace、pgbench 都跑起来，真实抓了一轮数据。
bpftrace 是什么
简单来说，bpftrace 是一个基于 eBPF 的动态追踪工具，语法有点像 awk + C 的混合体。你可以把一段小程序挂到某个事件上，当事件发生时执行统计、打印、聚合等动作。
它常用的探针大概有几类：
tracepoint：内核预定义的稳定事件，比如系统调用、块设备 IO。kprobe/kretprobe：动态挂到内核函数入口和返回处。uprobe/uretprobe：动态挂到用户态程序函数入口和返回处。usdt：用户态静态探针，PostgreSQL 就内置了一批 DTrace/USDT 探针。interval/END：定时或结束时输出聚合结果。
举个最简单的例子：
bpftrace -e 'tracepoint:syscalls:sys_exit_read /comm == "postgres"/ { @[pid] = count(); }'
这段脚本的意思就是：只要 postgres 进程退出 read 系统调用，就按 pid 计数。
看起来很简单，但它解决的是 PostgreSQL 自己不一定方便统计的问题。数据库内部视图如果把每一次 syscall、每一次 LWLock、每一次内核 IO 都统计进去，那开销和可移植性都会很麻烦。而 bpftrace 的价值在于：临时挂上去，观察一段时间，拿到证据，然后摘下来。
用完就走，不留感情包袱。
实验环境
这次实验环境如下：
OS : Rocky Linux 9.5 (Blue Onyx)
Kernel : 5.14.0-503.26.1.el9_5.x86_64
CPU : 2 cores
Memory : 8GB
PG : PostgreSQL 13.23，Rocky 官方包
bpftrace: v0.23.5
安装依赖：
dnf -y install bpftrace perf sysstat strace \
postgresql postgresql-server postgresql-contrib postgresql-devel \
systemtap-sdt-devel gcc make git
先验证 bpftrace 能否正常工作：
[root@lab ~]# bpftrace --version
bpftrace v0.23.5
[root@lab ~]# bpftrace -e 'BEGIN { printf("BPFTRACE_OK\n"); exit(); }'
Attaching 1 probe...
BPFTRACE_OK
接下来是关键点：PostgreSQL 是否带 USDT 探针。
这点非常重要。你脚本写得再漂亮，如果 PostgreSQL 编译时没有打开相关探针，最后也是竹篮打水一场空。
让我们看一下：
[root@lab ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:query*'
usdt:/usr/bin/postgres:postgresql:query__done
usdt:/usr/bin/postgres:postgresql:query__execute__done
usdt:/usr/bin/postgres:postgresql:query__execute__start
usdt:/usr/bin/postgres:postgresql:query__parse__done
usdt:/usr/bin/postgres:postgresql:query__parse__start
usdt:/usr/bin/postgres:postgresql:query__plan__done
usdt:/usr/bin/postgres:postgresql:query__plan__start
usdt:/usr/bin/postgres:postgresql:query__rewrite__done
usdt:/usr/bin/postgres:postgresql:query__rewrite__start
usdt:/usr/bin/postgres:postgresql:query__start
再看看锁相关探针：
[root@lab ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:lock*'
usdt:/usr/bin/postgres:postgresql:lock__wait__done
usdt:/usr/bin/postgres:postgresql:lock__wait__start
[root@lab ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:lwlock*'
usdt:/usr/bin/postgres:postgresql:lwlock__acquire
usdt:/usr/bin/postgres:postgresql:lwlock__acquire__or__wait
usdt:/usr/bin/postgres:postgresql:lwlock__acquire__or__wait__fail
usdt:/usr/bin/postgres:postgresql:lwlock__condacquire
usdt:/usr/bin/postgres:postgresql:lwlock__condacquire__fail
usdt:/usr/bin/postgres:postgresql:lwlock__release
usdt:/usr/bin/postgres:postgresql:lwlock__wait__done
usdt:/usr/bin/postgres:postgresql:lwlock__wait__start
可以看到，Rocky 官方 PostgreSQL 13.23 包已经带了 USDT 探针。这一点值得点赞，不用再单独源码编译了。
当然，如果你的环境里看不到这些探针，那就需要自己编译：
./configure --enable-dtrace --enable-debug CFLAGS='-O2 -g'
make -j
make install
准备测试实例
为了不污染系统 PostgreSQL，这里单独拉一个测试实例，端口使用 55432。
mkdir -p /tmp/pg_bpftrace_lab
chown -R postgres:postgres /tmp/pg_bpftrace_lab
runuser -u postgres -- initdb -D /tmp/pg_bpftrace_lab/data
追加一些方便观察的参数：
port = 55432
listen_addresses = '127.0.0.1'
shared_preload_libraries = 'pg_stat_statements'
track_io_timing = on
logging_collector = on
log_directory = 'log'
log_filename = 'postgresql.log'
log_line_prefix = '%m [%p] [%l] user=%u,db=%d,app=%a,client=%r '
log_min_duration_statement = 100
log_lock_waits = on
deadlock_timeout = '200ms'
log_temp_files = 0
log_checkpoints = on
log_autovacuum_min_duration = 0
work_mem = '1MB'
shared_buffers = '128MB'
max_wal_size = '256MB'
checkpoint_timeout = '30s'
启动：
runuser -u postgres -- pg_ctl -D /tmp/pg_bpftrace_lab/data \
-l /tmp/pg_bpftrace_lab/server.log start
确认版本：
postgres=# select version();
version
----------------------------------------------------------------------------------------------------------------
PostgreSQL 13.23 on x86_64-redhat-linux-gnu, compiled by gcc (GCC) 11.5.0 20240719 (Red Hat 11.5.0-11), 64-bit
(1 row)
准备三张实验表：
create extension if not exists pg_stat_statements;
create table lab_cpu as
select
i as id,
md5(i::text) as payload,
(random() * 1000000)::int as v
from generate_series(1, 800000) as s(i);
create table lab_sort as
select
i as id,
md5(random()::text) || md5(i::text) as payload,
(random() * 1000000)::int as v
from generate_series(1, 600000) as s(i);
create table lab_lock(id int primary key, payload text);
insert into lab_lock values (1, 'before');
analyze lab_cpu;
analyze lab_sort;
analyze lab_lock;
select pg_stat_statements_reset();
再初始化 pgbench：
runuser -u postgres -- pgbench -p 55432 -i -s 5 postgres
万事俱备，开整。
先看看传统手段
我们先跑几个负载。
CPU 型查询：
select count(*)
from lab_cpu
where md5(payload || id::text) like 'a%';
故意制造排序 spill：
set work_mem = '64kB';
create temp table sorted_lab_sort as
select * from lab_sort
order by payload;
再跑 pgbench：
runuser -u postgres -- pgbench -p 55432 -c 6 -j 2 -T 5 -P 2 postgres
从 pg_stat_statements 能看到什么？
query calls total_ms temp_blks_read temp_blks_written
UPDATE pgbench_branches ... 44032 197629.45 0 0
UPDATE pgbench_tellers ... 44032 162129.01 0 0
select pg_sleep($1) 1 5005.04 0 0
update lab_lock set payload=$1 where... 2 4004.70 0 0
create temp table sorted_lab_sort ... 2 2240.56 59351 63535
UPDATE pgbench_accounts ... 44032 1259.14 0 0
create temp table sorted_lab_sort2 ... 1 1120.25 29719 31812
copy pgbench_accounts from stdin 1 897.32 0 0
信息已经不少了：
pgbench_branches和pgbench_tellers更新耗时很高。sorted_lab_sort写了大量临时块。lab_lock的更新耗时约 4 秒，说明等待时间也会计入 SQL 总耗时。
再看日志，也能看到临时文件和锁等待：
LOG: duration: 151.922 ms statement: select count(*) from lab_cpu where md5(payload || id::text) like 'a%';
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp22184.0", size 18259968
LOG: duration: 1098.071 ms statement: set work_mem='64kB'; create temp table sorted_lab_sort as select * from lab_sort order by payload;
LOG: process 22224 still waiting for ShareLock on transaction 20903 after 200.062 ms
LOG: process 22224 acquired ShareLock on transaction 20903 after 4004.416 ms
LOG: duration: 4006.146 ms statement: update lab_lock set payload='waiter' where id=1;
这时候如果只是日常排障，基本已经能往下处理了。但如果我们想继续追问：
- 这段时间 query 延迟分布长啥样？
- 锁等待在 bpftrace 里能不能抓到？
- 临时文件对应系统调用层面 read/write 了多少？
- pgbench 压力下 LWLock 主要卡在哪里？
这就轮到 bpftrace 登场了。
实战一：抓 query 延迟
先抓 query 延迟，使用 query__start 和 query__done 两个 USDT 探针。
脚本如下：
usdt:/usr/bin/postgres:postgresql:query__start
{
@q[tid] = str(arg0);
@ts[tid] = nsecs;
}
usdt:/usr/bin/postgres:postgresql:query__done / @ts[tid] /
{
$lat_us = (nsecs - @ts[tid]) / 1000;
@latency_us = hist($lat_us);
if ($lat_us > 100000) {
printf("SLOW_QUERY pid=%d lat_us=%llu sql=%s\n", pid, $lat_us, @q[tid]);
}
delete(@q[tid]);
delete(@ts[tid]);
}
END
{
print(@latency_us);
}
这里我没有按 SQL 文本聚合，而是只保留一个全局延迟直方图，并打印超过 100ms 的 SQL。
为什么这么做？因为我一开始就掉坑了：直接拿完整 SQL 文本作为 map key，pgbench 一跑，立马报错：
WARNING: Map full; can't update element. Try increasing max_map_keys config
这个坑非常有代表性。高频事件里千万不要随便用完整 SQL 文本做高基数聚合，尤其简单协议下 SQL 里带字面量，map 很容易爆。
改完之后，真实输出如下：
Attaching 3 probes...
SLOW_QUERY pid=22178 lat_us=151947 sql=select count(*) from lab_cpu where md5(payload || id::text) like 'a%';
SLOW_QUERY pid=22184 lat_us=1098073 sql=set work_mem='64kB'; create temp table sorted_lab_sort as select * from lab_sort order by payload;
@latency_us:
[2, 4) 639 |@ |
[4, 8) 9423 |@@@@@@@@@@@@@@@@@@@ |
[8, 16) 788 |@ |
[16, 32) 25027 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[32, 64) 16179 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[64, 128) 3365 |@@@@@@ |
[128, 256) 367 | |
[256, 512) 2165 |@@@@ |
[512, 1K) 2598 |@@@@@ |
[1K, 2K) 7757 |@@@@@@@@@@@@@@@@ |
[2K, 4K) 3042 |@@@@@@ |
[4K, 8K) 596 |@ |
[8K, 16K) 61 | |
[128K, 256K) 1 | |
[1M, 2M) 1 | |
这个结果很直观：
- 大量 pgbench 短 SQL 落在微秒到几毫秒区间。
- CPU 型查询耗时 151ms，被
SLOW_QUERY打出来了。 - 排序 spill 查询耗时 1098ms，也被打出来了。
这里 bpftrace 和日志对得上：
LOG: duration: 151.922 ms statement: select count(*) ...
LOG: duration: 1098.071 ms statement: set work_mem='64kB'; create temp table ...
日志告诉我们哪条慢，bpftrace 还能顺便告诉我们整体延迟分布。
实战二：抓重量级锁等待
重量级锁等待使用 lock__wait__start 和 lock__wait__done。
脚本：
usdt:/usr/bin/postgres:postgresql:lock__wait__start
{
@ts[tid] = nsecs;
}
usdt:/usr/bin/postgres:postgresql:lock__wait__done / @ts[tid] /
{
$lat_ms = (nsecs - @ts[tid]) / 1000000;
@lock_wait_ms[pid] = hist($lat_ms);
delete(@ts[tid]);
}
END
{
print(@lock_wait_ms);
}
制造一个最简单的行锁等待：
-- 会话 1
begin;
update lab_lock set payload='holder' where id=1;
select pg_sleep(5);
commit;
-- 会话 2
update lab_lock set payload='waiter' where id=1;
bpftrace 抓到：
Attaching 3 probes...
@lock_wait_ms[22224]:
[2K, 4K) 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
日志里也能看到：
LOG: process 22224 still waiting for ShareLock on transaction 20903 after 200.062 ms
LOG: process 22224 acquired ShareLock on transaction 20903 after 4004.416 ms
LOG: duration: 4006.146 ms statement: update lab_lock set payload='waiter' where id=1;
为什么会话 1 睡了 5 秒，但等待只有 4 秒？因为会话 2 是 1 秒后才启动的，这个结果符合预期。
这里要说一句，定位具体谁堵谁，pg_locks 还是更直接；bpftrace 更适合看一段时间内所有锁等待的分布，比如有大量几十毫秒的短等待，日志可能不一定好看出来。
实战三：抓临时文件对应的 syscall IO
前面排序 spill 里，PostgreSQL 日志告诉我们产生了临时文件，pg_stat_statements 告诉我们写了大量临时块。
那系统调用层面到底 read/write 了多少？
脚本如下：
tracepoint:syscalls:sys_exit_read / comm == "postgres" && args.ret > 0 /
{
@read_bytes[pid] = sum(args.ret);
}
tracepoint:syscalls:sys_exit_pread64 / comm == "postgres" && args.ret > 0 /
{
@read_bytes[pid] = sum(args.ret);
}
tracepoint:syscalls:sys_exit_write / comm == "postgres" && args.ret > 0 /
{
@write_bytes[pid] = sum(args.ret);
}
tracepoint:syscalls:sys_exit_pwrite64 / comm == "postgres" && args.ret > 0 /
{
@write_bytes[pid] = sum(args.ret);
}
END
{
print(@read_bytes);
print(@write_bytes);
}
执行排序：
set work_mem='64kB';
create temp table sorted_lab_sort2 as
select * from lab_sort
order by payload;
真实输出如下：
Attaching 5 probes...
@read_bytes[22107]: 1
@read_bytes[22108]: 1
@read_bytes[22104]: 1664
@read_bytes[22243]: 67873495
@read_bytes[22244]: 95628365
@read_bytes[22242]: 127211682
@write_bytes[22107]: 1
@write_bytes[22104]: 1610
@write_bytes[22108]: 106497
@write_bytes[22106]: 229786
@write_bytes[22243]: 60556590
@write_bytes[22244]: 88475300
@write_bytes[22242]: 234283705
对应日志：
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp22243.0", size 12771328
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp22244.0", size 17522688
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp22242.0", size 21504000
LOG: duration: 1121.320 ms statement: set work_mem='64kB'; create temp table sorted_lab_sort2 as select * from lab_sort order by payload;
为什么有多个 pid？因为排序过程中启用了并行 worker，所以不止一个 postgres 进程产生读写。
这里的链路就很清楚了：
SQL 层：temp_blks_written 增加
日志层：出现 temporary file
内核层：postgres 进程产生明显 read/write syscall 字节数
这就是 bpftrace 很香的地方。它不是只看数据库自己怎么说，还能继续看数据库对内核做了什么。
实战四：分析内存使用
数据库里，内存分析也是一门很重要的手艺。
很多时候我们会遇到这种问题：
work_mem明明设置了，排序到底用了多少？- SQL 没有写临时文件，是不是就代表没有吃内存？
- 一个 backend 突然 RSS 涨了，到底是 PostgreSQL 内部申请，还是操作系统层面有大块 mmap？
- 线上不方便改代码，能不能先抓一把证据？
这类问题，bpftrace 也可以帮上忙。
不过这里先说一句实话：PostgreSQL 的内存管理主要在 MemoryContext 里，SQL 执行过程大量使用 palloc。如果你想完整理解内存生命周期，最好结合 pg_log_backend_memory_contexts()、MemoryContextStats、日志和进程 RSS 一起看。bpftrace 不是内存剖析的银弹，但它可以在“不改代码”的情况下，帮我们抓到一些非常关键的现场证据。
先看 PostgreSQL 自己暴露出来的排序探针：
[root@lab ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:*sort*'
usdt:/usr/bin/postgres:postgresql:sort__done
usdt:/usr/bin/postgres:postgresql:sort__start
写一个小脚本，观察排序开始时的 work_mem，以及排序结束时使用的空间：
usdt:/usr/bin/postgres:postgresql:sort__start
{
printf("SORT_START pid=%d begin=%d unique=%d nkeys=%d workmem=%d random=%d\n",
pid, arg0, arg1, arg2, arg3, arg4);
}
usdt:/usr/bin/postgres:postgresql:sort__done
{
printf("SORT_DONE pid=%d external=%d space=%lld\n", pid, arg0, arg1);
@sort_count[pid] = count();
@sort_space[pid] = sum(arg1);
}
END
{
print(@sort_count);
print(@sort_space);
}
这里有两个字段比较有用：
sort__start里的workmem，可以看到这个排序节点拿到的work_mem。sort__done里的external和space，可以看到这次排序是否变成外部排序，以及使用了多少空间。
先把 work_mem 压到很小：
set work_mem='64kB';
create temp table mem_sort_test as
select * from lab_sort
order by payload;
真实输出如下：
Attaching 6 probes...
SORT_START pid=22808 begin=1 unique=1 nkeys=2 workmem=65536 random=0
SORT_START pid=22808 begin=1 unique=0 nkeys=2 workmem=64 random=0
SORT_DONE pid=22808 external=0 space=25
SORT_DONE pid=22808 external=0 space=25
SORT_START pid=22808 begin=0 unique=0 nkeys=1 workmem=64 random=0
SORT_DONE pid=22808 external=1 space=6316
@sort_count[22808]: 3
@sort_space[22808]: 6366
最后这一行 external=1 space=6316 就比较直观了：这个排序没有老老实实待在内存里，而是变成了外部排序，空间大约 6316KB。
再把 work_mem 放大：
set work_mem='512MB';
create temp table mem_sort_inmem2 as
select * from lab_sort
order by payload;
真实输出如下：
Attaching 6 probes...
SORT_START pid=22847 begin=1 unique=1 nkeys=2 workmem=65536 random=0
SORT_START pid=22847 begin=1 unique=0 nkeys=2 workmem=524288 random=0
SORT_DONE pid=22847 external=0 space=25
SORT_DONE pid=22847 external=0 space=25
SORT_START pid=22847 begin=0 unique=0 nkeys=1 workmem=524288 random=0
SORT_DONE pid=22847 external=0 space=108952
@sort_count[22847]: 3
@sort_space[22847]: 109002
这次 external=0，说明排序在内存里完成；space=108952，大约 108MB。
这就能回答一个很常见的问题：没有临时文件，不代表 SQL 不吃内存。它可能只是 work_mem 足够大，排序留在内存里完成了。
再往下看一层，看看这个 backend 有没有向操作系统申请大块内存。这里抓 mmap 和 brk：
tracepoint:syscalls:sys_enter_mmap / comm == "postgres" /
{
@mmap_count[pid] = count();
@mmap_bytes[pid] = sum(args.len);
}
tracepoint:syscalls:sys_enter_brk / comm == "postgres" /
{
@brk_count[pid] = count();
}
END
{
print(@mmap_count);
print(@mmap_bytes);
print(@brk_count);
}
配合刚才的 512MB work_mem 排序，抓到结果如下：
Attaching 3 probes...
@mmap_count[22838]: 27
@mmap_bytes[22838]: 101756928
@brk_count[22838]: 14
也就是说，这个 backend 在采样窗口里发生了 27 次 mmap，累计申请长度约 101MB，同时还有 14 次 brk。
这里不要过度解读：mmap_bytes 是系统调用请求长度的累计，不等于最终 RSS，也不等于 PostgreSQL 某个 MemoryContext 的精确占用。它更像是在告诉我们：这个 SQL 执行过程中，backend 确实发生了明显的大块内存申请。
如果线上遇到某个 backend 内存飙升，我一般会这样组合拳：
第一步：从 pg_stat_activity 找 pid、SQL、等待事件；
第二步：用 /proc/<pid>/status 或 ps 看 RSS/VmSize；
第三步：必要时调用 pg_log_backend_memory_contexts(pid) 看 MemoryContext；
第四步：用 bpftrace 短时间抓 mmap/brk，确认 OS 层面是否有大块申请；
第五步：如果怀疑排序/哈希聚合，再抓 sort__start/sort__done 或结合执行计划看 Hash/Sort 节点。
这块最忌讳上来就全局抓 malloc/free。数据库系统调用频率很高，内存分配也非常频繁，抓太细很容易把观察者效应放大。先按 pid、短窗口、聚合输出，往往更靠谱。
实战五：抓 LWLock
LWLock 是今天最值得看的部分。
重量级锁还能靠 pg_locks 查，临时文件还能靠日志看，但 LWLock 很多时候就比较晦涩。pg_stat_activity.wait_event 可能告诉你在等某个 LWLock，但你很难进一步看到等待分布。
这里用 lwlock__wait__start 和 lwlock__wait__done 按 tranche 聚合：
usdt:/usr/bin/postgres:postgresql:lwlock__wait__start
{
@ts[tid] = nsecs;
@tranche[tid] = str(arg0);
}
usdt:/usr/bin/postgres:postgresql:lwlock__wait__done / @ts[tid] /
{
$delta_us = (nsecs - @ts[tid]) / 1000;
@lwlock_wait_us[@tranche[tid]] = sum($delta_us);
@lwlock_wait_count[@tranche[tid]] = count();
@lwlock_stack[ustack(10)] = sum($delta_us);
delete(@ts[tid]);
delete(@tranche[tid]);
}
END
{
print(@lwlock_wait_count);
print(@lwlock_wait_us);
print(@lwlock_stack);
}
跑一轮高并发 pgbench：
runuser -u postgres -- pgbench -p 55432 -c 40 -j 4 -T 10 -P 5 postgres
pgbench 结果：
progress: 5.0 s, 2502.2 tps, lat 15.693 ms
progress: 10.0 s, 2218.2 tps, lat 18.019 ms
number of clients: 40
duration: 10 s
number of transactions actually processed: 23642
latency average = 16.842 ms
tps = 2355.617370
bpftrace 抓到的 LWLock 等待如下：
@lwlock_wait_count[SyncRep]: 2
@lwlock_wait_count[XactSLRU]: 24
@lwlock_wait_count[WALBufMapping]: 41
@lwlock_wait_count[XidGen]: 51
@lwlock_wait_count[ProcArray]: 62
@lwlock_wait_count[WALInsert]: 386
@lwlock_wait_count[BufferContent]: 1775
@lwlock_wait_count[LockManager]: 3798
@lwlock_wait_count[WALWrite]: 35214
@lwlock_wait_us[SyncRep]: 2
@lwlock_wait_us[WALBufMapping]: 68
@lwlock_wait_us[XidGen]: 79
@lwlock_wait_us[ProcArray]: 624
@lwlock_wait_us[XactSLRU]: 633
@lwlock_wait_us[WALInsert]: 6074
@lwlock_wait_us[BufferContent]: 10291
@lwlock_wait_us[LockManager]: 97419
@lwlock_wait_us[WALWrite]: 26186806
这就很有意思了。
按等待次数看，WALWrite 有 35214 次；按累计等待时间看，WALWrite 也最突出，累计约 26.18 秒。其次是 LockManager、BufferContent、WALInsert。
这和 pgbench 场景是匹配的：大量小事务频繁更新、提交，WAL 写入路径自然容易被打得比较热。
如果只看 pg_stat_statements，我们能看到：
UPDATE pgbench_branches ... total_ms 197629.45
UPDATE pgbench_tellers ... total_ms 162129.01
但是 bpftrace 进一步告诉我们：这轮压力下，LWLock 层面最突出的等待在 WALWrite。
一个真实踩坑：ustack 只有地址
上面的脚本里，我也加了 ustack(10)，原本是想抓用户态调用栈。结果抓出来是这样的：
@lwlock_stack[
0x55d99cf924ed
0
]: 659
@lwlock_stack[
0x55d99cf920ca
0
]: 2522
是不是有点尴尬？只有地址，没有函数名。
看一下系统包：
[root@lab ~]# file /usr/bin/postgres
/usr/bin/postgres: ELF 64-bit LSB pie executable, x86-64, ... stripped
[root@lab ~]# readelf -S /usr/bin/postgres | grep -i debug
[30] .gnu_debuglink PROGBITS
[31] .gnu_debugdata PROGBITS
系统包的 postgres 是 stripped 的，所以 ustack() 没法直接给我们漂亮的函数名。
这也是生产上很常见的坑。你以为抓调用栈很潇洒，结果抓出来一堆地址，瞬间索然无味。
要解决这个问题，可以考虑：
- 安装对应的 debuginfo 包；
- 自编译 PostgreSQL，打开
--enable-debug； - 编译时加
-fno-omit-frame-pointer，让栈展开更友好； - perf 场景下使用
--call-graph dwarf。
所以生产中我建议先抓 tranche 聚合，这个已经很有价值；如果还要继续看函数路径，再准备 debug 环境。
生产使用建议
这次实验下来，有几点感受比较深。
观察者效应
首先必须承认，bpftrace 一定会有观察者效应。
所谓观察者效应，简单理解就是：你为了观察系统而加上的探针，本身也会改变系统的行为。只不过这个影响有大有小，有时候可以忽略，有时候就会很明显。
bpftrace 的开销主要来自几个地方：
- 探针触发频率：比如 syscall、LWLock、query start/done，在高并发场景下都可能非常频繁。
- 探针动作复杂度：只是
count()和sum()，通常还好；如果每次都printf()，开销就会明显上来。 - map key 基数：按 pid、tranche 聚合比较稳；按完整 SQL 文本、路径、随机字符串聚合，很容易爆。
- 调用栈采集：
ustack()/kstack()很有价值，但成本也更高。 - 输出频率：终端疯狂刷屏，本身就是额外负担。
这次我就真实踩到了一个坑：一开始按完整 SQL 文本作为 map key 聚合 query 延迟，pgbench 一跑，立刻出现：
WARNING: Map full; can't update element. Try increasing max_map_keys config
这不仅说明脚本写法不够优雅，也提醒我们：生产环境里 bpftrace 不是想怎么挂就怎么挂。
所以我的建议是：
- 先低频、短时间采样：比如先抓 10 秒、30 秒，不要一上来常驻。
- 先聚合，少打印：优先
count()、sum()、hist()，少在高频路径里printf()。 - 先粗后细：先按 pid、tranche、SQL 总延迟看方向，再决定是否抓栈。
- 慎用调用栈：
ustack()很香，但不要默认每个脚本都加，尤其是高频事件。 - 控制 key 基数：不要随便用完整 SQL、完整路径作为 map key。
- 避开业务高峰：除非正在救火，否则尽量在可控窗口使用。
- 有对照数据：采样前后看一下 TPS、延迟、CPU，确认 bpftrace 本身没有把问题放大。
简单来说，bpftrace 很适合“短、平、快”地拿证据，不适合没想清楚就长期挂着。
第一，bpftrace 很强，但不要一上来就用。
大多数 PostgreSQL 问题，先看 pg_stat_activity、pg_stat_statements、pg_locks、日志，已经能解决一大半。bpftrace 更适合用在“还差最后一公里”的场景。
第二，脚本要控制 key 的基数。
这次 Map full 就是血淋淋的例子。不要在高频事件里随便用完整 SQL 文本、完整路径、大量随机字符串做 map key。生产里更建议：
- 先看全局 hist；
- 用 pid、tranche、queryid 这类可控 key；
- 慢 SQL 用
printf抽样； - 短时间采样，拿到证据就撤。
第三，优先使用稳定探针。
PostgreSQL USDT 和 Linux tracepoint 相对稳定；uprobe/kprobe 更灵活，但也更依赖版本、符号和编译选项。
第四，不要疯狂 printf。
高频事件里一直 printf，工具本身就可能制造开销。更推荐用 map 聚合，最后通过 END 或 interval 输出。
第五，提前准备符号信息。
如果你想看漂亮的 PostgreSQL 函数栈，最好提前准备 debuginfo 或 debug build。不然你看到的可能就是一串地址。
小结
这次总算把 bpftrace 真正跑起来了，也抓到了一些挺有代表性的结果：
- query 延迟：抓到了 151ms 的 CPU 型 SQL 和 1098ms 的排序 spill SQL。
- lock wait：抓到了真实行锁等待，耗时约 4004ms。
- syscall IO：排序 spill 期间，抓到了多个 postgres 进程的 read/write 字节数。
- memory：排序探针抓到了外部排序约 6316KB、内存排序约 108MB，
mmap侧也抓到约 101MB 的申请。 - LWLock：高并发 pgbench 下，
WALWrite等待最突出，35214 次，累计约 26.18 秒。
我觉得 bpftrace 对 DBA 最大的意义，不是多一个炫技工具，而是让我们能把数据库现象和系统行为真正连起来。
pg_stat_statements 告诉你哪类 SQL 慢，日志告诉你出现了临时文件和锁等待，而 bpftrace 可以继续往下问：
它在 PostgreSQL 内部和内核层，到底卡在哪里？
这才是 bpftrace 最有价值的地方。
本文实验脚本
文中的脚本都已经完整贴出，也可以按下面的名称拆成独立 .bt 文件复用：
pg_query_latency.bt
pg_lock_wait.bt
pg_syscall_io.bt
pg_sort_mem.bt
pg_mem_syscall.bt
pg_lwlock_stack.bt
参考
- Analyzing postgres performance problems using perf and eBPF, Andres Freund
- Party tricks for PostgreSQL perf, ftrace and bpftrace, Dmitrii Dolgov
- PostgreSQL & DTrace Lightning Talk, Robert Lor
- PostgreSQL Documentation: Dynamic Tracing
- Brendan Gregg: eBPF / perf / FlameGraph 相关资料