Go应用日志写入卡顿陷入netpoll等待问题排查求助

核心问题定位 #

写入100KB以上XML格式trace日志时，触发固定120-125秒延迟，卡顿发生在(*os.File) Write阶段，goroutine处于netpoll的IO等待状态，延迟时长与数据大小无关，环境为64位AMD Linux Docker容器，使用Go 1.22.5 + zap logger。

可能原因分析 #

• IO目标的超时阻塞逻辑：即使是文件写入，若日志输出目标是管道/远程日志服务，或是本地文件关联了特殊的日志收集进程，当数据量超过100KB时，接收端触发了120秒的批量处理超时逻辑，导致write操作陷入IO等待。
• 自定义系统的IO层限制：自定义Linux系统可能在文件系统（如overlay2缓存策略）、IO调度器或挂载参数上做了特殊配置，当写入数据达到阈值时触发批量flush的超时机制，刚好匹配120秒的延迟时长。
• zap同步写入的放大效应：zap的lockedWriteSyncer是带锁的同步写入，若底层文件描述符被设置为非阻塞模式，当写入缓冲区满时，Go runtime会通过netpoll等待IO就绪，若此时底层存储的就绪信号被延迟120秒触发，就会出现固定延迟。
• 内核参数异常配置：自定义系统可能错误配置了IO相关内核参数（如文件缓存刷新超时、fd等待超时），导致大文件写入时触发预设的120秒等待逻辑。

进一步调试建议 #

• 确认日志输出目标：检查zap配置的WriteSyncer指向本地文件、管道还是远程服务，若为后者直接排查接收端的超时逻辑。
• 替换测试写入目标：临时将日志输出改为/dev/shm下的tmpfs文件，验证延迟是否消失，排除底层存储的问题。
• strace跟踪系统调用：在容器内执行strace -p <pid> -e trace=write,fsync，捕捉卡顿期间的系统调用细节，确认是write等待还是fsync阻塞。
• 排查宿主机IO状态：在宿主机用iostat -x 1查看磁盘负载、队列情况，用dmesg检查是否有IO错误；对比标准Linux系统，检查自定义系统的文件系统挂载参数。
• 调整zap写入策略：临时改用zap的异步写入模式，或替换为无锁WriteSyncer，验证延迟是否与同步写入机制相关。
• 核对内核参数：对比标准Linux系统，检查容器内/proc/sys/fs/、/proc/sys/net/下的IO相关参数，重点关注超时、缓存类配置。

栈跟踪信息 #

goroutine 660 gp=0xc000603180 m=nil [IO wait]:
runtime.gopark(0xc0002be1a0?, 0x10101139100?, 0x80?, 0x92?, 0xb?)
    /usr/lib/go/src/runtime/proc.go:402 +0xce fp=0xc0006515e0 sp=0xc0006515c0 pc=0x44358e
runtime.netpollblock(0x48cf3b?, 0x40b146?, 0x0?)
    /usr/lib/go/src/runtime/netpoll.go:573 +0xf7 fp=0xc000651618 sp=0xc0006515e0 pc=0x43c1d7
internal/poll.runtime_pollWait(0x7bca99ea4d48, 0x77)
    /usr/lib/go/src/runtime/netpoll.go:345 +0x85 fp=0xc000651638 sp=0xc000651618 pc=0x4714e5
internal/poll.(*pollDesc).wait(0xc000059320?, 0xc000dde000?, 0x1)
    /usr/lib/go/src/internal/poll/fd_poll_runtime.go:84 +0x27 fp=0xc000651660 sp=0xc000651638 pc=0x4ef447
internal/poll.(*pollDesc).waitWrite(...)
    /usr/lib/go/src/internal/poll/fd_poll_runtime.go:93
internal/poll.(*FD).Write(0xc000059320, {0xc000dbe000, 0x351d7, 0x36000})
    /usr/lib/go/src/internal/poll/fd_unix.go:388 +0x2d9 fp=0xc000651710 sp=0xc000651660 pc=0x4f27d9
os.(*File).write(...)
    /usr/lib/go/src/os/file_posix.go:46
os.(*File).Write(0xc00078e210, {0xc000dbe000?, 0x351d7, 0xc0003c6a40?})
    /usr/lib/go/src/os/file.go:189 +0x51 fp=0xc000651770 sp=0xc000651710 pc=0x4fc031
go.uber.org/zap/zapcore.(*lockedWriteSyncer).Write(0xc0000ea0a8, {0xc000dbe000?, 0x2b06a37fd?, 0x200a460?})
    /home/rodion/my/oam-agent/out/.cache/go-pkg/go.uber.org/zap@v1.27.0/zapcore/write_syncer.go:66 +0x6c fp=0xc0006517b8 sp=0xc000651770 pc=0xe1956c
go.uber.org/zap/zapcore.(*ioCore).Write(0xc00048f260, {0xfc, {0xc1e40920854e5dcd, 0x2b06a37fd, 0x200a460}, {0x0, 0x0}, {0xc000d88000, 0x351b2}, {0x0, ...}, ...}, ...)
    /home/rodion/my/oam-agent/out/.cache/go-pkg/go.uber.org/zap@v1.27.0/zapcore/core.go:99 +0xb5 fp=0xc000651888 sp=0xc0006517b8 pc=0xe0c975
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0009a00d0, {0x0, 0x0, 0x0})
    /home/rodion/my/oam-agent/out/.cache/go-pkg/go.uber.org/zap@v1.27.0/zapcore/entry.go:253 +0x11c fp=0xc000651a18 sp=0xc000651888 pc=0xe0ebdc

内容的提问来源于stack exchange，提问作者Rodion Gorkovenko