深入浅出 bpftrace
xiongcc约 21 分钟前言
很早之前就想写一篇关于 bpftrace 分析 PostgreSQL 的文章了。
原因也很简单，日常排查 PostgreSQL 问题时，我们已经习惯了先看 pg_stat_activity、pg_stat_statements、pg_locks，再结合数据库日志、操作系统指标综合分析。大多数问题到这里基本就能有个眉目。
但是总有一些场景，让人看得云里雾里：
1.pg_stat_statements 里 SQL 很慢，但慢在 CPU、锁、IO，还是系统调用？2.明明 shared_blks_read 很高，但到底有没有真正落到内核 IO？3.wait_event 看到 LWLock，但到底卡在什么路径上？4.临时文件写了不少，但系统调用层面读写了多少？5.PostgreSQL 自己的统计视图看不到的东西，还有没有办法继续往下挖？
这时候 bpftrace 就很有意思了。
它不是替代 PostgreSQL 视图的工具，而是帮我们把观察范围从 PostgreSQL 内部继续往下打穿，打到系统调用、内核 tracepoint、用户态 USDT 探针、甚至函数调用栈。
以前看 Andres Freund、Dmitrii Dolgov 关于 perf/eBPF/bpftrace 的分享，觉得思路非常漂亮，但光看材料总有种“隔靴搔痒”的感觉。于是这次我专门准备了一台 Rocky Linux 9.5 云主机，把 PostgreSQL、bpftrace、pgbench 都跑起来，真实抓了一轮数据。(文章使用 CodeX + GPT 在真实环境上生成)
bpftrace 是什么
简单来说，bpftrace 是一个基于 eBPF 的动态追踪工具，语法有点像 awk + C 的混合体。你可以把一段小程序挂到某个事件上，当事件发生时执行统计、打印、聚合等动作。
它常用的探针大概有几类：
1.tracepoint：内核预定义的稳定事件，比如系统调用、块设备 IO。2.kprobe/kretprobe：动态挂到内核函数入口和返回处。3.uprobe/uretprobe：动态挂到用户态程序函数入口和返回处。4.usdt：用户态静态探针，PostgreSQL 就内置了一批 DTrace/USDT 探针。5.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_64CPU : 2 coresMemory : 8GBPG : 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@iv-yemjqp9qm8s6iplx9rez ~]# bpftrace --versionbpftrace v0.23.5[root@iv-yemjqp9qm8s6iplx9rez ~]# bpftrace -e 'BEGIN { printf("BPFTRACE_OK\n"); exit(); }'Attaching 1 probe...BPFTRACE_OK
接下来是关键点：PostgreSQL 是否带 USDT 探针。
这点非常重要。你脚本写得再漂亮，如果 PostgreSQL 编译时没有打开相关探针，最后也是竹篮打水一场空。
让我们看一下：
[root@iv-yemjqp9qm8s6iplx9rez ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:query*'usdt:/usr/bin/postgres:postgresql:query__doneusdt:/usr/bin/postgres:postgresql:query__execute__doneusdt:/usr/bin/postgres:postgresql:query__execute__startusdt:/usr/bin/postgres:postgresql:query__parse__doneusdt:/usr/bin/postgres:postgresql:query__parse__startusdt:/usr/bin/postgres:postgresql:query__plan__doneusdt:/usr/bin/postgres:postgresql:query__plan__startusdt:/usr/bin/postgres:postgresql:query__rewrite__doneusdt:/usr/bin/postgres:postgresql:query__rewrite__startusdt:/usr/bin/postgres:postgresql:query__start
再看看锁相关探针：
[root@iv-yemjqp9qm8s6iplx9rez ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:lock*'usdt:/usr/bin/postgres:postgresql:lock__wait__doneusdt:/usr/bin/postgres:postgresql:lock__wait__start[root@iv-yemjqp9qm8s6iplx9rez ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:lwlock*'usdt:/usr/bin/postgres:postgresql:lwlock__acquireusdt:/usr/bin/postgres:postgresql:lwlock__acquire__or__waitusdt:/usr/bin/postgres:postgresql:lwlock__acquire__or__wait__failusdt:/usr/bin/postgres:postgresql:lwlock__condacquireusdt:/usr/bin/postgres:postgresql:lwlock__condacquire__failusdt:/usr/bin/postgres:postgresql:lwlock__releaseusdt:/usr/bin/postgres:postgresql:lwlock__wait__doneusdt:/usr/bin/postgres:postgresql:lwlock__wait__start
可以看到，Rocky 官方 PostgreSQL 13.23 包已经带了 USDT 探针。这一点值得点赞，不用再单独源码编译了。
当然，如果你的环境里看不到这些探针，那就需要自己编译：
./configure --enable-dtrace --enable-debug CFLAGS='-O2 -g'make -jmake install
准备测试实例
为了不污染系统 PostgreSQL，这里单独拉一个测试实例，端口使用 55432。
mkdir -p /tmp/pg_bpftrace_labchown -R postgres:postgres /tmp/pg_bpftrace_labrunuser -u postgres -- initdb -D /tmp/pg_bpftrace_lab/data
追加一些方便观察的参数：
port = 55432listen_addresses = '127.0.0.1'shared_preload_libraries = 'pg_stat_statements'track_io_timing = onlogging_collector = onlog_directory = 'log'log_filename = 'postgresql.log'log_line_prefix = '%m [%p] [%l] user=%u,db=%d,app=%a,client=%r 'log_min_duration_statement = 100log_lock_waits = ondeadlock_timeout = '200ms'log_temp_files = 0log_checkpoints = onlog_autovacuum_min_duration = 0work_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 startpostgres=# 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 asselecti as id,md5(i::text) as payload,(random() * 1000000)::int as vfrom generate_series(1, 800000) as s(i);create table lab_sort asselecti as id,md5(random()::text) || md5(i::text) as payload,(random() * 1000000)::int as vfrom 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_cpuwhere md5(payload || id::text) like 'a%';
故意制造排序 spill：
set work_mem = '64kB';create temp table sorted_lab_sort asselect * from lab_sortorder 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_writtenUPDATE pgbench_branches ... 44032 197629.45 0 0UPDATE pgbench_tellers ... 44032 162129.01 0 0select pg_sleep($1) 1 5005.04 0 0update lab_lock set payload=$1 where... 2 4004.70 0 0create temp table sorted_lab_sort ... 2 2240.56 59351 63535UPDATE pgbench_accounts ... 44032 1259.14 0 0create temp table sorted_lab_sort2 ... 1 1120.25 29719 31812copy pgbench_accounts from stdin 1 897.32 0 0
信息已经不少了：
1.pgbench_branches 和 pgbench_tellers 更新耗时很高。2.sorted_lab_sort 写了大量临时块。3.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 18259968LOG: 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 msLOG: process 22224 acquired ShareLock on transaction 20903 after 4004.416 msLOG: duration: 4006.146 ms statement: update lab_lock set payload='waiter' where id=1;
这时候如果只是日常排障，基本已经能往下处理了。但如果我们想继续追问：
1.这段时间 query 延迟分布长啥样？2.锁等待在 bpftrace 里能不能抓到？3.临时文件对应系统调用层面 read/write 了多少？4.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 | |
这个结果很直观：
1.大量 pgbench 短 SQL 落在微秒到几毫秒区间。2.CPU 型查询耗时 151ms，被 SLOW_QUERY 打出来了。3.排序 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);}
制造一个最简单的行锁等待：
-- 会话 1begin;update lab_lock set payload='holder' where id=1;select pg_sleep(5);commit;-- 会话 2update 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 msLOG: process 22224 acquired ShareLock on transaction 20903 after 4004.416 msLOG: 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 asselect * from lab_sortorder 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 12771328LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp22244.0", size 17522688LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp22242.0", size 21504000LOG: 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 很香的地方。它不是只看数据库自己怎么说，还能继续看数据库对内核做了什么。
实战四：分析内存使用
数据库里，内存分析也是一门很重要的手艺。
很多时候我们会遇到这种问题：
1.work_mem 明明设置了，排序到底用了多少？2.SQL 没有写临时文件，是不是就代表没有吃内存？3.一个 backend 突然 RSS 涨了，到底是 PostgreSQL 内部申请，还是操作系统层面有大块 mmap？4.线上不方便改代码，能不能先抓一把证据？
这类问题，bpftrace 也可以帮上忙。
不过这里先说一句实话：PostgreSQL 的内存管理主要在 MemoryContext 里，SQL 执行过程大量使用 palloc。如果你想完整理解内存生命周期，最好结合 pg_log_backend_memory_contexts()、MemoryContextStats、日志和进程 RSS 一起看。bpftrace 不是内存剖析的银弹，但它可以在“不改代码”的情况下，帮我们抓到一些非常关键的现场证据。
先看 PostgreSQL 自己暴露出来的排序探针：
[root@iv-yemjqp9qm8s6iplx9rez ~]# bpftrace -l 'usdt:/usr/bin/postgres:postgresql:*sort*'usdt:/usr/bin/postgres:postgresql:sort__doneusdt:/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);}
这里有两个字段比较有用：
1.sort__start 里的 workmem，可以看到这个排序节点拿到的 work_mem。2.sort__done 里的 external 和 space，可以看到这次排序是否变成外部排序，以及使用了多少空间。
先把 work_mem 压到很小：
set work_mem='64kB';create temp table mem_sort_test asselect * from lab_sortorder by payload;
真实输出如下：
Attaching 6 probes...SORT_START pid=22808 begin=1 unique=1 nkeys=2 workmem=65536 random=0SORT_START pid=22808 begin=1 unique=0 nkeys=2 workmem=64 random=0SORT_DONE pid=22808 external=0 space=25SORT_DONE pid=22808 external=0 space=25SORT_START pid=22808 begin=0 unique=0 nkeys=1 workmem=64 random=0SORT_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 asselect * from lab_sortorder by payload;
真实输出如下：
Attaching 6 probes...SORT_START pid=22847 begin=1 unique=1 nkeys=2 workmem=65536 random=0SORT_START pid=22847 begin=1 unique=0 nkeys=2 workmem=524288 random=0SORT_DONE pid=22847 external=0 space=25SORT_DONE pid=22847 external=0 space=25SORT_START pid=22847 begin=0 unique=0 nkeys=1 workmem=524288 random=0SORT_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 postgrespgbench 结果：
progress: 5.0 s, 2502.2 tps, lat 15.693 msprogress: 10.0 s, 2218.2 tps, lat 18.019 msnumber of clients: 40duration: 10 snumber of transactions actually processed: 23642latency average = 16.842 mstps = 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.45UPDATE pgbench_tellers ... total_ms 162129.01
但是 bpftrace 进一步告诉我们：这轮压力下，LWLock 层面最突出的等待在 WALWrite。
一个真实踩坑：ustack 只有地址
上面的脚本里，我也加了 ustack(10)，原本是想抓用户态调用栈。结果抓出来是这样的：
@lwlock_stack[0x55d99cf924ed0]: 659@lwlock_stack[0x55d99cf920ca0]: 2522
是不是有点尴尬？只有地址，没有函数名。
看一下系统包：
[root@iv-yemjqp9qm8s6iplx9rez ~]# file /usr/bin/postgres/usr/bin/postgres: ELF 64-bit LSB pie executable, x86-64, ... stripped[root@iv-yemjqp9qm8s6iplx9rez ~]# readelf -S /usr/bin/postgres | grep -i debug[30] .gnu_debuglink PROGBITS[31] .gnu_debugdata PROGBITS
系统包的 postgres 是 stripped 的，所以 ustack() 没法直接给我们漂亮的函数名。
这也是生产上很常见的坑。你以为抓调用栈很潇洒，结果抓出来一堆地址，瞬间索然无味。
要解决这个问题，可以考虑：
1.安装对应的 debuginfo 包；2.自编译 PostgreSQL，打开 --enable-debug；3.编译时加 -fno-omit-frame-pointer，让栈展开更友好；4.perf 场景下使用 --call-graph dwarf。
所以生产中我建议先抓 tranche 聚合，这个已经很有价值；如果还要继续看函数路径，再准备 debug 环境。
生产使用建议
这次实验下来，有几点感受比较深。
观察者效应
首先必须承认，bpftrace 一定会有观察者效应。
所谓观察者效应，简单理解就是：你为了观察系统而加上的探针，本身也会改变系统的行为。只不过这个影响有大有小，有时候可以忽略，有时候就会很明显。
bpftrace 的开销主要来自几个地方：
1.探针触发频率：比如 syscall、LWLock、query start/done，在高并发场景下都可能非常频繁。2.探针动作复杂度：只是 count() 和 sum()，通常还好；如果每次都 printf()，开销就会明显上来。3.map key 基数：按 pid、tranche 聚合比较稳；按完整 SQL 文本、路径、随机字符串聚合，很容易爆。4.调用栈采集：ustack() / kstack() 很有价值，但成本也更高。5.输出频率：终端疯狂刷屏，本身就是额外负担。
这次我就真实踩到了一个坑：一开始按完整 SQL 文本作为 map key 聚合 query 延迟，pgbench 一跑，立刻出现：
WARNING: Map full; can't update element. Try increasing max_map_keys config这不仅说明脚本写法不够优雅，也提醒我们：生产环境里 bpftrace 不是想怎么挂就怎么挂。
所以我的建议是：
1.先低频、短时间采样：比如先抓 10 秒、30 秒，不要一上来常驻。2.先聚合，少打印：优先 count()、sum()、hist()，少在高频路径里 printf()。3.先粗后细：先按 pid、tranche、SQL 总延迟看方向，再决定是否抓栈。4.慎用调用栈：ustack() 很香，但不要默认每个脚本都加，尤其是高频事件。5.控制 key 基数：不要随便用完整 SQL、完整路径作为 map key。6.避开业务高峰：除非正在救火，否则尽量在可控窗口使用。7.有对照数据：采样前后看一下 TPS、延迟、CPU，确认 bpftrace 本身没有把问题放大。
简单来说，bpftrace 很适合“短、平、快”地拿证据，不适合没想清楚就长期挂着。
第一，bpftrace 很强，但不要一上来就用。
大多数 PostgreSQL 问题，先看 pg_stat_activity、pg_stat_statements、pg_locks、日志，已经能解决一大半。bpftrace 更适合用在“还差最后一公里”的场景。
第二，脚本要控制 key 的基数。
这次 Map full 就是血淋淋的例子。不要在高频事件里随便用完整 SQL 文本、完整路径、大量随机字符串做 map key。生产里更建议：
1.先看全局 hist；2.用 pid、tranche、queryid 这类可控 key；3.慢 SQL 用 printf 抽样；4.短时间采样，拿到证据就撤。
第三，优先使用稳定探针。
PostgreSQL USDT 和 Linux tracepoint 相对稳定；uprobe/kprobe 更灵活，但也更依赖版本、符号和编译选项。
第四，不要疯狂 printf。
高频事件里一直 printf，工具本身就可能制造开销。更推荐用 map 聚合，最后通过 END 或 interval 输出。
第五，提前准备符号信息。
如果你想看漂亮的 PostgreSQL 函数栈，最好提前准备 debuginfo 或 debug build。不然你看到的可能就是一串地址。
小结
这次总算把 bpftrace 真正跑起来了，也抓到了一些挺有代表性的结果：
1.query 延迟：抓到了 151ms 的 CPU 型 SQL 和 1098ms 的排序 spill SQL。2.lock wait：抓到了真实行锁等待，耗时约 4004ms。3.syscall IO：排序 spill 期间，抓到了多个 postgres 进程的 read/write 字节数。4.memory：排序探针抓到了外部排序约 6316KB、内存排序约 108MB，mmap 侧也抓到约 101MB 的申请。5.LWLock：高并发 pgbench 下，WALWrite 等待最突出，35214 次，累计约 26.18 秒。
我觉得 bpftrace 对 DBA 最大的意义，不是多一个炫技工具，而是让我们能把数据库现象和系统行为真正连起来。
pg_stat_statements 告诉你哪类 SQL 慢，日志告诉你出现了临时文件和锁等待，而 bpftrace 可以继续往下问：
它在 PostgreSQL 内部和内核层，到底卡在哪里？
这才是 bpftrace 最有价值的地方。
本文实验脚本
本文相关脚本已整理在本地：
pg_bpftrace_lab/bpftrace/pg_query_latency.btpg_bpftrace_lab/bpftrace/pg_lock_wait.btpg_bpftrace_lab/bpftrace/pg_syscall_io.btpg_bpftrace_lab/bpftrace/pg_sort_mem.btpg_bpftrace_lab/bpftrace/pg_mem_syscall.btpg_bpftrace_lab/bpftrace/pg_lwlock_stack.bt
参考
1.Analyzing postgres performance problems using perf and eBPF, Andres Freund2.Party tricks for PostgreSQL perf, ftrace and bpftrace, Dmitrii Dolgov3.PostgreSQL & DTrace Lightning Talk, Robert Lor4.PostgreSQL Documentation: Dynamic Tracing5.Brendan Gregg: eBPF / perf / FlameGraph 相关资料