故障排查——SQLite在PoleFS上的同步异常

cuixiaogang

根因定位:PoleFS 客户端的文件同步请求长期停留在 S3 上传签名前的脏数据读取路径,反复进行范围查询、内存分配并引发 GC;高度怀疑读取零进度循环,但未直接取得现场返回值。停止 SQLite 使用进程未解除异常,重启客户端并重新挂载后恢复。本次完成的是服务恢复,不是客户端缺陷修复。

现象

PoleFS 客户端持续占用约一个逻辑 CPU,常驻内存约 5.5 GiB。挂载目录中运行着使用 SQLite WAL 的监控程序。

客户端实时采样结果如下。CPU 百分比按单个逻辑 CPU 为 100% 计。

1
2
3
4
5
采样1: 3.01秒; 整机非空闲=9.5%; iowait=2.7%
目标进程CPU=100.3%

采样2: 3.01秒; 整机非空闲=14.9%; iowait=2.9%
目标进程CPU=98.7%

另一次 5 秒采样区分了用户态与内核态消耗。

1
2
3
4
用户态CPU%: 100.8
内核态CPU%: 1.6
主缺页/秒: 0.0
线程数: 58

SQLite 所在进程还出现了不可中断等待。最终取得的内核栈表明,它正在等待文件同步完成。

环境

项目 本次环境
故障日期 2026 年 11 月 10 日
系统内核 Linux 5.10.134-14.an8.x86_64
逻辑 CPU 32 个
文件系统 PoleFS,挂载类型为 fuse.polefs
挂载点 /public_data
后端访问 客户端调用链中使用 AWS SDK for Go 访问 S3 后端
应用 Python 监控程序,使用 SQLite WAL 文件组
客户端二进制 Go 程序,常规符号已裁剪,保留 .gopclntab
客户端管理方式 遗留在登录会话 scope 中,不是专用 systemd 服务
客户端版本 未取得明确版本号
SQLite 版本与同步配置 未取得,不推定 synchronous、checkpoint 阈值等实际设置

本文隐藏主机、账号、域名、认证参数和个人路径。保留 PoleFS 名称及函数名,用于说明本案的实现特点。命令中的 <占位符> 需要替换后执行,不能直接照抄。

排查过程

一、确认不是整机 CPU 满载

机器有 32 个逻辑 CPU。进程占用约 100%,表示约占满一个逻辑 CPU,而不是整机使用率达到 100%。整机采样也未显示 CPU 已耗尽。

目标进程的消耗主要在用户态,主缺页为零。因此先调查客户端自身的计算路径,而不是把原因归为整机算力不足或频繁换入页面。

后续热点线程在多个线程间变化,不能只根据主线程显示的 S 状态判断进程空闲。

二、用 perf 采样,先解决符号映射问题

当前会话无权读取 root 客户端的 I/O、文件描述符和性能数据,因此需要在 SSH 终端通过 sudo 执行相关命令。

最初使用 perf top,采样进程进入了 T 状态,未正常结束。这是诊断命令被暂停,不是目标客户端进入相同状态。随后改用非交互式采样,并设置强制退出兜底。

1
2
3
4
5
6
7
8
PERF_DIR=$(mktemp -d /tmp/polefs-perf.XXXXXX)

sudo timeout --kill-after=3s 15s \
perf record -o "$PERF_DIR/perf.data" \
-F 49 -e cpu-clock:u -p <客户端PID> -- sleep 10

sudo perf report -i "$PERF_DIR/perf.data" \
--stdio --percent-limit 0 --sort comm,dso,symbol

本次采集到 481 个样本,无丢失。报告起初只显示地址。

1
2
3.12%  polefs-client  polefs-client  [.] 0x0000000000734c67
2.08% polefs-client polefs-client [.] 0x00000000006e1745

直接把报告中的地址交给 Go 地址解析工具,曾错误映射到 Gob、HTTP 函数。完整报告出现了低于代码加载区的地址,促使重新核对 ELF 加载基址。

1
2
readelf -l /usr/bin/polefs-client
sudo perf script -i "$PERF_DIR/perf.data" -F ip,dso

本次二进制为 ELF EXEC,可执行加载段从 0x400000 开始。perf script 输出的原始指令地址,与报告显示的未解析偏移相差 0x400000。

报告显示地址 原始指令地址 正确函数
0x734c67 0xb34c67 fs.(*block).readRange
0x6e1745 0xae1745 backend.(*Range).Less
0x12fdb 0x412fdb runtime.mallocgc

该基址修正只适用于本次二进制和报告格式,不能作为所有 perf 地址的通用加法。优先解析原始指令地址,并核对采样二进制是否匹配。

使用保留的 Go 行号表解析原始地址,再按函数汇总。

1
2
3
4
5
6
sudo perf script -i "$PERF_DIR/perf.data" -F ip \
| awk '{print "0x"$1}' \
| go tool addr2line /usr/bin/polefs-client \
| awk 'NR%2==1 {count[$0]++; total++} END {for (f in count) printf "%6.2f%% %4d %s\n", 100*count[f]/total, count[f], f}' \
| sort -nr \
| head -n 30

主要结果如下。

1
2
3
4
5
6
7
8
9
10
30.56%  147 runtime.mallocgc
11.23% 54 polefs/internal/pkg/btree.(*node).iterate
5.20% 25 polefs/internal/client/fs.(*block).ReadDirty
4.78% 23 polefs/internal/client/fs.(*block).readRange
4.37% 21 polefs/internal/pkg/btree.items.find
3.74% 18 polefs/internal/client/fs.(*block).readDirtyData
3.33% 16 sort.Search
3.33% 16 runtime.deductAssistCredit
3.12% 15 polefs/internal/client/fs.(*part).Read
2.91% 14 polefs/internal/backend.(*Range).Less

范围查找、脏数据读取和内存分配成为主要方向。此时只有自身热点,还不能证明这些函数之间的调用关系,也不能把 mallocgc 的全部时间算作 GC。

三、I/O 增量很小,不支持大流量读写解释

查看 5 秒内的进程 I/O 计数变化。

1
sudo sh -c 'cat /proc/<客户端PID>/io; sleep 5; cat /proc/<客户端PID>/io'
计数 起点 5 秒后 增量
rchar 7414014317608 7414014317881 273 字节
wchar 6070685366824 6070685367103 279 字节
syscr 2205242581 2205242586 5 次
syscw 570085334 570085339 5 次
read_bytes 2670166016 2670166016 0
write_bytes 230727680 230727680 0

这些计数不能直接等同于共享文件业务吞吐或远端存储流量,但说明该窗口内没有大量读写系统调用。

这削弱了“大量正常 I/O 导致高 CPU”的解释。不过它与先前的 CPU 样本不在同一窗口,仍需调用链确认。

四、通过本机 pprof 找到完整调用链

检查文件描述符后,发现客户端有本机可访问的 HTTP 监听端口;二进制也包含 net/http/pprof。实际请求确认了诊断接口可用。

以下端口为本次发现的端口,不应假定其他部署相同。请求从本机发出,不经过代理。

1
2
curl --noproxy '*' --fail --max-time 5 \
'http://127.0.0.1:42289/debug/pprof/goroutine?debug=1'

通过同一接口采集 10 秒 CPU profile,再用 go tool pprof 分析自身和累计热点。本次实际使用本机 Python HTTP 客户端完成采集;以下为等价复查命令。

1
2
3
4
5
6
7
8
9
DIAG_DIR=$(mktemp -d /tmp/polefs-diag.XXXXXX)
chmod 700 "$DIAG_DIR"

curl --noproxy '*' --fail --max-time 18 \
-o "$DIAG_DIR/cpu.pprof" \
'http://127.0.0.1:42289/debug/pprof/profile?seconds=10'

go tool pprof -top /usr/bin/polefs-client "$DIAG_DIR/cpu.pprof"
go tool pprof -top -cum /usr/bin/polefs-client "$DIAG_DIR/cpu.pprof"

采样持续 10.10 秒,累计 CPU 样本为 14.63 秒,相当于平均约使用 1.45 个逻辑 CPU。

调用路径 累计样本占比
buffer.flushDirty 64.52%
AWS SDK Request.Sign 64.39%
signingCtx.buildBodyDigest 64.11%
part.Read 63.98%
block.ReadDirty 54.82%
后台 GC runtime.gcBgMarkWorker 30.83%

累计占比存在包含关系,不能逐行相加。 摘要生成和脏数据读取属于同一上层调用链。

调用方向为:文件同步请求进入 SyncFile,经 FlushFile、flushDirty 和 flush 调用 S3 putObject;AWS SDK 在签名前计算请求体摘要,读取请求体时进入 part.Read、ReadDirty 和 B 树范围查询。

因此,热点不是简单的 SHA-256 算法计算,而主要是计算摘要所需的数据读取路径。内存中的读取和整理可以持续消耗 CPU,而不产生大量网络 I/O。

五、日志关联到 SQLite WAL,但不把关联当作全部因果

客户端日志反复出现同一 inode 的读取失败。

1
2026-11-10T10:25:03.300+0800 ERROR fs/buffer.go:390 [ReadFile] InvalidRange, no data in backend, inode(18315880), offset(4124152), len(4096), backend fsize(4124152), buf.fsize(4276592), nNeed(520), err: data not in buffer

这里客户端记录的文件大小比后端大 152440 字节。读取走到后端文件末尾,需要缓冲区补充数据,但没有取得所需内容。

大小暂时不同可以是待刷写状态;最终返回读取错误才是本次异常证据。 不能仅凭这条日志证明数据库已损坏。

通过挂载级文件句柄查询定位 inode,避免递归扫描整个共享目录。

1
2
sudo timeout --kill-after=3s 15s lsof -nP +f -- /public_data \
| awk 'NR==1 || /18315880/'

匹配结果为一个 Python 进程打开的测试数据库 WAL 文件。脱敏后的关键字段如下。

1
2
COMMAND    PID          USER    FD TYPE DEVICE SIZE/OFF NODE     NAME
python3.1 <测试进程PID> <用户> 4u REG 0,57 4280712 18315880 /public_data/<用户>/<项目>/data/state_test.db-wal

同一进程还打开了对应的主数据库和 -shm 文件。这确定了读取失败文件的身份,但没有直接取得热点同步请求对应的文件标识,不能声称已经证明二者为同一文件。

六、停止测试进程后 CPU 不降,排除简单的新请求驱动

测试进程被停止后,旧 PID 消失,但客户端 CPU 连续三次仍为:

1
2
3
96.0%
98.3%
99.0%

随后再次查询测试库文件组,没有发现新进程打开它们,未取得守护进程重新拉起该工作负载的证据。

但扩大检查整个挂载后,发现另一监控进程仍打开非测试数据库,并有大量数据库句柄。同一进程多个句柄不能单独证明连接泄漏,也不能排除其他工作负载。

这个进程的两个线程都处于 D 状态。内核栈的关键部分为:

1
2
3
4
5
6
request_wait_answer [fuse]
fuse_simple_request [fuse]
fuse_fsync_common [fuse]
fuse_fsync [fuse]
do_fsync
__x64_sys_fdatasync

另一个线程停在关闭文件的 FUSE 路径:

1
2
3
4
rwsem_down_write_slowpath
fuse_flush [fuse]
filp_close
__x64_sys_close

由此确认:至少一个应用在等待 FUSE 文件同步回复,另一个线程关闭文件时也受阻。用户态的同步热点与内核等待相互吻合,但尚未按请求 ID 完成一一关联。

七、固定位置重复读取,反汇编发现零进度保护缺口

连续三次读取详细协程栈。

1
2
curl --noproxy '*' --fail --max-time 5 \
'http://127.0.0.1:42289/debug/pprof/goroutine?debug=2'

同一个 runnable 协程的关键参数保持相同:

  • 同一个 part、block 和 S3 请求对象。
  • ReadDirty 偏移为 0x300000,即 3 MiB。
  • 传入切片长度为 0xff0,即 4080 字节。
  • 执行位置在 ReadDirty、日志调用和 B 树遍历间变化。

优化后的 Go 栈参数可能不完全准确,因此这属于强线索,而不是直接测量读取返回值。

维护方源码不可得,转而只读反汇编本机二进制。本次函数地址如下,换版本后必须重新定位。

1
2
objdump -d --start-address=0xb34340 --stop-address=0xb345a0 /usr/bin/polefs-client
objdump -d --start-address=0xb51000 --stop-address=0xb51440 /usr/bin/polefs-client

反汇编显示:ReadDirty 调用下层读取并返回,重复读取的循环实际在 part.Read 中。它根据返回字节数更新当前位置、剩余长度和累计读取量;当前分析的路径未见明确的零进度退出保护。

因此,如果下层返回零字节,且没有触发其他退出条件,读取位置和剩余长度可能都不变化,而循环继续。

此外,每次 ReadDirty 都会构造 Debug 日志参数,其中包含接口装箱。即使日志最终不输出,参数构造仍可能带来开销。这与热点中的分配、GC 相符,但不是唯一的分配来源。

根因

已确认的故障本质是 PoleFS 的文件同步处理长期不完成,应用因此阻塞在 FUSE 同步等待中;其主要 CPU 消耗位于上传签名前的脏数据读取与范围索引处理,并伴随明显内存分配和 GC。

证据分级如下。

层次 结论 状态
直接故障 客户端同步处理持续高 CPU,应用等待同步回复 已确认
具体缺陷 读取在固定位置无法推进,调用方缺少零进度保护而忙循环 高度怀疑,未直接取得 n、err 返回值
文件异常 测试库 WAL 出现后端与缓冲数据衔接失败 已确认
触发源 SQLite WAL 的访问模式触发了当前异常同步请求 强关联,未证明热点请求属于该 WAL
数据结果 数据库是否损坏、重启前哪些数据尚未持久化 未验证

SQLite 与 PoleFS 的机制适配风险

SQLite 的正确性不仅要求能读写文件,还要求可靠的锁、缓存一致性以及同步和写入顺序保障。

SQLite 操作 对文件系统的要求
多连接访问 文件锁和共享状态能正确协调访问者
事务同步 fsync、fdatasync 提供约定的持久化和顺序保障
WAL 读取与复用 文件内容、大小、截断和缓存视图保持一致
默认 WAL 索引 同一主机的访问者通过映射 -shm 文件共享索引与协调状态

SQLite 官方明确说明,WAL 不适用于网络文件系统,同一数据库的所有访问进程必须位于同一主机。不同机器映射同名远程文件,并不等价于共享 SQLite 所需的内存协调机制。

本次未观察到跨主机访问,所以不能把故障归为已经证实的跨主机共享内存失效。同主机访问也不足以证明该远程挂载满足全部锁、缓存和同步要求。

PoleFS 本次同步路径还涉及脏范围整理、请求体读取、摘要计算和上传。SQLite 的小粒度写入、同步及 WAL 复用,可能放大这些操作的成本;但性能不匹配本身不能解释永不推进的循环,后者仍指向客户端实现问题。

不能泛化成所有 FUSE 都不能运行 SQLite,也不能声称所有远程文件系统必然损坏数据库。 实际可靠性取决于实现、配置和部署;没有明确兼容性保证时,不应将活跃 SQLite WAL 数据库放在本次这种远程共享挂载上。

解决

一、明确恢复边界

本次恢复前确认了:监控程序可以停止,相关数据风险可接受,整个 /public_data 暂时不用。

同时列出挂载使用者,确认除数据库外还有 Shell、开发工具和 Git 进程,避免只停止一个进程就直接重启整个文件系统。

1
2
sudo timeout --kill-after=3s 15s lsof -nP +f -- /public_data
sudo systemctl status <客户端PID> --no-pager -l

客户端属于登录会话 scope,而非专用服务。未对该 scope 执行整体重启。

帮助信息确认,启动参数 -o 是 owner 字符串,不能把形如 Pid:... 的值误解成进程监控配置。

二、保存重启资料,再停止客户端

停止前,将以下内容保存到新建的 root 私有目录中:

  • /proc/<客户端PID>/cmdline。
  • /proc/<客户端PID>/environ。
  • 原工作目录。

这些文件可能含认证信息,不能打印、公开上传或提交到仓库。

客户端停止后,确认原客户端和阻塞的监控进程都已退出。此时才进入旧挂载清理。

不能将此流程简化为直接强杀后凭记忆拼接命令。 必须先确认重新挂载所需参数和环境可用,并接受未刷写数据丢失风险。

三、清理断开的旧挂载

普通卸载失败。

1
sudo timeout --kill-after=2s 10s umount /public_data
1
umount: /public_data: target is busy.

继续检查时返回:

1
Cannot stat /public_data: Transport endpoint is not connected

这表示旧 FUSE 挂载还在,但对应客户端已经退出。占用可能来自原有进程的工作目录、打开文件或内存映射。

在共享挂载停用、影响已确认的前提下,执行懒卸载。

1
2
3
cd /
sudo umount -l /public_data
findmnt -M /public_data

本次 findmnt 无输出,确认旧挂载已从当前命名空间移除。

懒卸载不是刷写,也不是修复。 它不会让原进程的旧挂载引用自动变成新挂载引用。原开发工具需要退出重开,Shell 需先离开旧目录,再进入新挂载。

四、按保存的参数重新启动

实际恢复使用 Python 读取保存的 NUL 分隔参数和环境,不通过 shell 拼接命令,也不打印凭据。检查挂载不存在、程序路径和原工作目录正确后,使用 subprocess.Popen 启动,并设置:

  • start_new_session=True,使前台客户端脱离当前终端会话。
  • 标准输入指向空设备。
  • 标准输出和错误输出写入 root 私有日志。
  • 保留原参数、环境和工作目录,不同时调整缓存或刷写配置。

这是本次应急启动方式,不等于已建立持久的服务托管和自动恢复机制。

五、验证恢复结果

重新挂载后检查:

1
2
findmnt -M /public_data
timeout --kill-after=2s 5s stat /public_data

挂载类型恢复为 fuse.polefs,根目录 stat 正常返回。随后连续三次采样,每次 2 秒。

1
2
3
4
5
采样1: CPU=0.5%
采样2: CPU=0.5%
采样3: CPU=3.5%
VmRSS: 31148 kB
Threads: 15
项目 恢复前 恢复后
客户端 CPU 多次约 100%,停止应用后仍为 96%~99% 三次为 0.5%、0.5%、3.5%
常驻内存 约 5.5 GiB 约 30.4 MiB
线程数 58 15
文件系统状态 同步请求长时间不返回,应用进入 D 状态 新挂载根目录访问正常

验证范围仅覆盖客户端运行、挂载根目录和短时 CPU,未完成数据库完整性及全部业务文件读写验证。 重启使异常现场消失,但没有修复二进制中的潜在缺陷。

防复发

以下为本案后续措施,未在本次记录中验证全部实施完成。

活跃数据库退出共享挂载

用途 放置方式
单机监控的活跃 SQLite 数据库 放在确认属于本地磁盘、支持相关语义的文件系统
可丢弃测试库 在本地重新建库
数据库备份 用 SQLite 备份机制生成一致性快照,再上传 PoleFS
静态数据库副本 可作为文件保存,需要查询时优先下载到本地
多机并发读写 使用客户端/服务器数据库,或由数据所在主机提供数据库访问 API

目录叫 /data 或位于家目录,并不代表一定是本地磁盘。迁移前检查实际文件系统。

1
findmnt -T /准备存放数据库的目录

不要把正在使用的主 .db 文件直接复制成完整备份,已提交事务可能还在 WAL 中。

不用弱化事务保障掩盖问题

  • 改为回滚日志模式可以避开 WAL 的共享内存要求,但仍依赖正确的锁和同步,不保证绕过客户端同步缺陷。
  • 不把 synchronous=OFF 当作修复方案。
  • 不靠扩大缓存、降低日志级别或修改刷写间隔替代读取循环修复。
  • 不在故障现场盲目执行 checkpoint、全局 sync 或删除 WAL。

建立托管与诊断边界

  • 为客户端规划明确的服务管理方式,保留安全的启动配置和恢复流程,避免依赖遗留登录会话。
  • 不贸然配置无限自动重启,应先定义未刷写数据的风险处理方式。
  • 同时监控持续 CPU、GC、同步延迟、D 状态进程及重复范围读取错误。
  • pprof 可能暴露内部调用栈和运行信息,应限制网络可达性;本次通过本机访问不代表监听端口仅绑定回环地址。
  • 恢复资料和采样文件按敏感诊断资料管理,在不再需要时按内部凭据管理流程清理。

关键知识点总结

知识点 可复用结论
进程 CPU 100% 通常表示一个逻辑 CPU,不等于整机满载
用户态高 CPU 与低 I/O 可能是内存计算、范围查询或忙循环,不能只看磁盘和网络吞吐
Go 性能分析 裁剪常规符号后仍可能保留 .gopclntab;解析前核对原始指令地址和二进制匹配关系
pprof 统计 flat 是自身消耗,cum 包含下游,嵌套累计值不能直接相加
mallocgc 包含内存分配路径,不等于全部时间都在 GC;GC 应结合对应调用栈判断
零进度读取 循环必须考虑非空缓冲下读取不推进的情况,避免位置不变仍无界重试
D 状态 表示不可中断等待;本案通过内核栈确认在 FUSE 同步与关闭路径受阻,而不是仅凭状态猜测磁盘故障
FUSE 断开 客户端退出后旧挂载可能保留,并返回 Transport endpoint is not connected
懒卸载 移除路径上的挂载关系,不保证旧引用消失,也不会刷写未持久化数据
SQLite WAL 对同主机共享状态、锁和同步有要求,不能把远程共享文件当作普通本地文件使用
恢复与修复 重启后 CPU 回落证明恢复有效,不证明具体缺陷、数据完整性或兼容性问题已经解决

本案的长期处理方向是将活跃 SQLite 数据库迁出 PoleFS,并保留客户端读取循环的缺陷线索。PoleFS 用于备份或静态副本,不再直接承载这类活跃 WAL 工作负载。

参考资料: