本地服务不该这么慢:一次 800ms 延迟的排查

我有一个自建的 RSS 阅读器,后端常年跑在家里的一台 Mac 上,通过内网穿透对外服务。这台机器就在局域网里,没有跨地域网络,没有外部 API 调用,就是个挂着 SQLite 的小后端——按道理,它不该慢。可它偏偏会偶发地慢:绝大多数请求几十毫秒返回,但每隔一阵,某个请求会突然飙到几百毫秒、甚至一秒以上。刷新一下又好了,没有规律。

第一反应是“内存紧张、被写进 swap 了”——本地服务不该慢,那大概率是资源层面的问题。但这个解释太笼统,解释不了为什么有的毛刺跟并发有关,有的又只在 idle 之后才出现。真去把日志和排查记录翻出来对,才发现这个“偶发高延迟”根本不是一个问题,而是三个互相独立的根因叠在一起——我最初的直觉,只蒙对了其中一个。

先揪最大的那根刺:并发卡顿

打开视图时的 ~800ms 卡顿最容易复现,也最好下手,于是先查它。后端每次读列表都会对所有 feed 做一次新鲜度检查,过期的就触发一次抓取。better-sqlite3 是同步的,Node 又是单线程,于是一次性 fan-out N 个过期 feed,就把 N 段 parse + persist 全压在事件循环上,把同时进来的所有请求一起堵死。

这个和内存、swap 都没关系,是单线程被同步任务堵死的经典问题——而且当时还在纯 Node 上就把它修掉了:给刷新加了 single-flight 去重加并发上限(提交 b125d47)。修完之后,同样的并发场景峰值从 ~800ms 降到 84msdigest 列表从 ~800ms 降到 37 到 84ms

第一根刺拔掉了,但毛刺没有消失,说明还有别的根因在起作用。

第二根刺:WAL 不收缩

继续翻日志,发现另一类变慢跟并发无关,是写入随着时间慢慢变沉。SQLite 的自动 checkpoint 会把已提交的页写回主库,但原地复用 WAL 文件、从不缩小它,于是写入会随着 WAL 膨胀慢慢变慢。解法是加一个周期性的 TRUNCATE checkpoint 把 -wal 收回去。这是 SQLite 的行为,跟用什么语言无关,Node 和 Go 都得处理。

这两个根因都在 Node 内部修掉了,可日志里还留着一类没解释的毛刺:idle 一阵子之后,第一个请求特别容易慢。

真正难啃的那根刺:idle 唤醒税

这才是和内存、压缩、swap 真正相关的那个,也是我一开始直觉指向、却说不清机制的那个。后端是一个没有界面的 launchd 后台进程,idle 一两分钟后 macOS 会把它判成不活跃,压缩、甚至换出它的常驻内存。等下一个请求进来,这些页得先解压或从磁盘换回,第一次访问就付一笔唤醒税。日志里的数据很典型:idle 90 秒后是 28ms,150 秒是 50ms,可到了 120 秒就变成 800ms,隔两三分钟能到 831ms。非确定性,取决于 idle 期间系统压力有多大。

值得把这一下拆成两层。触发和机制全在系统层:macOS 压缩、缺页、解压或从磁盘换回,这套跟用什么语言无关。但这一下有多狠,是 Node 层决定的,关键在 V8 的 GC。idle 之后第一个请求的分配很容易触发一次回收,而 GC 要扫描整个存活堆,于是它不是“用到哪页换回哪页”,而是把之前被压缩的整块 V8 堆一次性全 fault 回来。尖刺因此和堆大小成正比,而不是和这次请求的实际工作集成正比——堆平均 46M、峰值 156M,这一下自然就是几百毫秒。better-sqlite3 又是同步的,整个换回过程还阻塞着那唯一的线程,直接摊进请求耗时。

到这里三个根因才算拆干净:一个是并发 bug,已经在 Node 里修掉;一个是 SQLite 的 WAL 行为,跟语言无关;第三个才是内存压缩带来的 swap 税,也是唯一一个和“本地服务不该这么慢”这个直觉真正对上号的根因。真正促成我把后端重写成 Go 的,正是它。前两个在 Node 里已经能修;第三个的本质是“这个进程常驻了太多可被压缩、可被换出的内存”,而这一点,只能靠换掉运行时来根治。

为什么 Node 天生是 swap 的重灾区

决定一个进程会不会被 swap 的,既不是它的总内存占用,也不是存活对象大小,而是它那部分“脏的、匿名的、还被引用着的”页有多大。内核只认物理页,按可回收性分三类:

  • 干净的文件页,比如可执行文件的代码段。压力来了直接丢弃,需要时再从磁盘读回,不进 swap
  • MADV_FREE 标记过的页,运行时“释放了但还没还给系统”的内存。内核零成本直接回收,不压缩也不写盘。
  • 脏的匿名页,堆上还在用的对象、栈。回收它只能压缩或写进 swap。这一类才是 swap 的来源。

V8 的堆几乎全落在第三类。这就是为什么一个 Node 服务在内存紧张时特别容易被换出,而换出后又特别容易被 GC 反复扫到、触发一连串缺页——这正是 idle 唤醒税里那些成串又无规律的毛刺的来源。

换成 Go 之后:同一套监控怎么说

这个项目的后台每 5 分钟采一次资源样本,Node 和 Go 是逐行对齐的移植,采样字段完全一样。于是我手上有一份跨越迁移点的、同一管线打出来的监控数据——不是估算,是实测。

指标(同一监控管线)Node(约 19 天,5490 次采样)Go(稳态)
常驻内存 RSS平均 161M,峰值 406M约 29 到 49M
运行时存活堆平均 46M,峰值 156M约 1.6 到 3M

存活堆平均从 46M 掉到 3M 上下,差不多 15 倍——这一栏就是 V8 消失的直接体现。RSS 峰值那一栏也说明问题:Node 有过冲到 406M 的时候,那种时刻正是它给整机内存压力添的柴。

要看清 swap 暴露面,还得用 vmmap,它能给出每类页的 dirty 和 swapped 明细。我把它同时对准生产在跑的 Go、以及在同机、指向同一份数据库副本重新拉起来的 Node:

vmmap 明细NodeGo
physical footprint147.9M29.1M(峰值 51.5M)
脏匿名页(swap 候选面)142.8M42.2M
代码段常驻(干净、永不 swap)200.6M165.7M

这里也顺带解开一个我一直没对上的数:我印象里 Node 是“120MB 左右”,可 RSS 明明两百多兆。原因是活动监视器那列“内存”显示的是 physical footprint,不是 RSS——RSS 把大量共享库常驻页和空闲保留内存都算了进去,footprint 才是 macOS 真正记在进程头上、用来判断压力的数。

降幅为何比数字更大

只看 footprint,是 148M 到 29M,约 5 倍。但对 swap 风险来说,真正的降幅更大,原因在“成分”:

Node 的内存几乎全是脏的、无处可逃的。 它的脏匿名页 142.8M,占 footprint 的百分之九十七——没有可免费回收的缓冲,压力一来这一百四十多兆整块都得压缩或写盘,内核白捡不到一页。

Go 自带一层免费回收的垫子。 Go 的 footprint 是 29M,但它 RSS 里还有约 37M 是 MADV_FREE 的空闲堆,压力下内核直接丢弃、零成本,压根不算进 footprint。所以 Go 真正“逼不得已才 swap”的面,比 42M 还小。

Node 只涨不退,Go 涨完会还。 Node 的峰值 footprint 约等于稳态,吃进去不吐;Go 峰值 51.5M 出现在后台抓取一批 feed 时,事后收缩回 29M,两次任务之间把内存还给系统。

合起来:切到 Go 后,这个服务在内存吃紧时“被写进 swap”的暴露面,大约缩到原来的三分之一到五分之一,而且从“整块都得 swap”变成“绝大部分能被免费回收,只剩个位到十几兆的真实脏工作集”。落到 idle 唤醒税上,就是唤醒时需要被压缩、被换回的页少了一个数量级,GC 撞上换出页的概率也随之下降。迁移后的 burst 实测,稳态 p50 是 13ms、p99 是 15ms。

再往里拆一层,能变成延迟的更少。 42.2M 是“最坏可能被换出”的上界,但真正能拖慢请求的,只有还被引用着的活内存——换出后会被请求碰到、或被 GC 每轮重扫的那部分。按 vmmap 的分区明细,这 42.2M 里约 30M 就是上面那层 MADV_FREE 空闲堆(碰不到、免费回收,不产生 fault),剩下的活工作集只有约 5M:1.6M 的 Go 存活堆,加约 3M 活的 SQLite/C 分配。而 GC 每轮真正重扫的热面,只有那 1.6M。换句话说,能转成请求延迟的是个位 M,不是 42M。Node 那边正相反:142.8M 几乎全是 V8 的活堆,GC 每轮要扫整个几十上百兆,任何一块被换出都会在下次 GC 里 fault 回来——这才是两边 idle 唤醒毛刺差距真正的根。

诚实的边界

Go 不是魔法,有几件事得说清楚:

idle 唤醒税是被“减轻”,不是“消除”。 macOS 会压缩任何 idle 进程的常驻内存,跟语言无关。更小的 footprint 让要被压缩、换回的页更少,唤醒税更小,但只要进程 idle 够久,第一笔税照付。而且被压的很大一块是 mmap 进来的那份 439M 数据库页缓存,这部分 Node 和 Go 一样躲不掉

SQLite 的原生开销一分没省。 老的 better-sqlite3 同样是原生 SQLite,页缓存和 C 侧 malloc 跟 Go 的 mattn/go-sqlite3 花的是同一份钱。Go 现在剩下的那点脏工作集,主体恰恰就是它。

所以一个 Go 加 cgo-SQLite 的服务,内存地板本就不低,落在三四十兆是正常的,别指望掉到十兆。真正消失的那一百多兆,是 V8 的 JS 堆加上运行时生成的 JIT 代码——它们全是脏匿名页,也正是最能被 swap 的那类。省掉 V8,就是这次迁移对延迟的全部贡献。

复现方法

想量自己进程的 swap 暴露面,不用装任何东西,vmmap 就够了:

# 拿到进程 pid 后
vmmap -summary <pid> | grep -iE "Physical footprint|Writable regions|swapped"

盯两个数:Physical footprint 是 macOS 真正记在进程头上的内存,Writable regions 里的 written / dirty 才是压力来时可能被写进 swap 的面。RSS 会同时高估这两者,别拿它下结论。

收尾:那句“本地服务不该这么慢”,说对了几分

回头看,最初那句“本地服务不该这么慢”只说对了三分之一。这个偶发 800ms 是三个互不相关的根因叠出来的:单线程被同步 fan-out 堵死(跟 swap 无关,Node 内就修掉了)、WAL 不收缩(语言无关)、以及 idle 唤醒时的内存压缩税(唯一真正和 swap 有关的那个)。一开始把三个都归给“内存紧张”,是把排查抄了近道;真正拆开之后,才知道该在哪一层动手——迁移到 Go 精准解决的是第三个,靠的是把常驻的脏内存、也就是 swap 暴露面砍掉大半。搞清楚哪个问题归哪一层,比笼统甩锅给 swap 有用得多。