无人值守的自动 dump（二）

之前在这篇无人值守（一）[1]简单介绍了我们针对线上抖动问题定位的工具的设计思路，思路很简单，技术含量很低，是个人都可以想得到，但是它确实帮我们查到了很多很难定位的问题。

在本篇里，我们重点讲一讲这个工具[2]在生产环境帮我们发现了哪些问题。

OOM 类问题

RPC decode 未做防御性编程，导致 OOM

应用侧的编解码可能是非官方实现(如 node 之类的无官方 SDK 的项目)，在一些私有协议 decode 工程中会读诸如 list len 之类的字段，如果外部编码实现有问题，发生了字节错位，就可能会读出一个很大的值。

非标准 app ----encode-------> 我们的应用 decode -----> Boom!

decoder 实现都是需要考虑这种情况的，类似这样[3]。如果对请求方的数据完全信任，碰到对方的 bug 或者恶意攻击，可能导致自己的服务 OOM。

在线上实际发现了一例内存瞬间飚升的 case，收到报警后，我们可以看到：

1: 1330208768 [1: 1330208768] @ 0x11b1df3 0x11b1bcb 0x119664e 0x11b1695 0x1196f77 0x11a956a 0x11a86c7 0x1196724 0x11b1695 0x11b1c29 0x119664e 0x11b1695 0x11b1c29 0x119664e 0x11b1695 0x11b1c29 0x119664e 0x11bb360 0x168f143 0x179c2fc 0x1799b70 0x179acd6 0x16d3306 0x16d1088 0xf59386 0xf59474 0xf54e5f 0xf54987 0xf539f1 0xf6043a 0xcd8c0d 0x49b481
....下面是表示栈内容的，这不重要

1: 1330208768 [1: 1330208768] 表示 inuse_objects : inuse_space [alloc_objects : alloc_space]，这里可以看到一个对象就直接用掉了 1GB 内存，显然不是正常情况，查看代码后，发现有未进行大小判断而完全信任用户输入数据包的 decode 代码。

修复起来很简单，像前面提到的 async-h1 一样加个判断就可以了。

tls 开启后线上进程占用内存上涨，直至 OOM

线上需要做全链路加密，所以有开启 tls 的需求，但开启之后发现内存一路暴涨，直至 OOM，工具可以打印如下堆栈：

heap profile: 1460: 27614136 [45557: 1080481472] @ heap/1048576
727: 23822336 [730: 23920640] @ 0xc56b96 0xc591e8 0xc58e68 0xc59ed1 0xdd55ff 0xde15b8 0xde13ef 0xde09e9 0xde050c 0x13bfa13 0x13bf475 0x14c33d0 0x14c49f8 0x14cb398 0x14bffab 0x14cdf78 0xddcf90 0x45eda1
# 0xc56b95  *****mtls/crypto/tls.(*block).reserve+0x75   *****mtls/crypto/tls/conn.go:475

查阅老版本的 Go 代码，发现其 TLS 的 write buffer 会随着写出的数据包大小增加而逐渐扩容，其扩容逻辑比较简单：

func (b *block) reserve(n int) {
 if cap(b.data) >= n {
  return
 }
 m := cap(b.data)
 if m == 0 {
  m = 1024
 }
 for m < n {
  m *= 2
 }
 data := make([]byte, len(b.data), m)
 copy(data, b.data)
 b.data = data
}

初始为 1024，后续不够用每次扩容为两倍。但是阅读 tls 的代码后得知，这个写出的数据包大小最大实际上只有 16KB + 额外的一个小 header 大小左右，但老版本的实现会导致比较多的空间浪费，因为最终会扩容到 32KB。

这段比较浪费空间的逻辑在 Go1.12 之后已经进行了优化：

func sliceForAppend(in []byte, n int) (head, tail []byte) {
 if total := len(in) + n; cap(in) >= total {
  head = in[:total]
 } else {
  head = make([]byte, total)
  copy(head, in)
 }
 tail = head[len(in):]
 return
}

变成了需要多少，分配多少的朴实逻辑。所以会比老版本在这个问题上有不少缓解，不过在我们的场景下，新版本的代码依然没法满足需求，所以还需要进一步优化，这就是后话了。

goroutine 暴涨类问题

本地 app GC hang 死，导致 goroutine 卡 channel send

在我们的程序中有一段和本地进程通信的逻辑，write goroutine 会向一个 channel 中写数据，按常理来讲，同物理机的两个进程通过网络通信成本比较低，类似下面的代码按说不太可能出问题：

concurrently:
taskChan <- task

consumer:
for task := range taskChan {
    // 憋一些 task 一起写
    localConnection.write(task 们)
}

看起来问题不大，但是线上经常都有和这个 channel send 相关的抖动，我们通过工具拿到的现场：

2020-11-03 08:00:05,950 [ERROR] [diag.goroutine] [diagnose] pprof goroutine, config_min : 3000, config_diff : 25, config_abs : 200000,  previous : [41402 44257 47247 50085 52795 55509 29762 32575 35451 38460], current : 55509, profile : goroutine profile: total 55513
40844 @ 0x46daaf 0x4433ab 0x443381 0x443165 0xf551f7 0x12fd2e7 0x12fc94f 0x13f41d5 0x13fc45f 0xf43ee4 0xcd8c0d 0x49b481
#    ****channel.Send 这是个假的栈，你理解意思就行了
# 

当前憋了 5w 个 goroutine，有 4w 个卡在 channel send 上，这个 channel 的对面还是一条本地连接，令人难以接受。

但是要考虑到，线上的业务系统是 Java，Java 发生 FGÇ 的时候可不是闹着玩的。对往本地连接的 write buffer 写数据一定不会卡的假设是有问题的。

既然出问题了，说明在这里对我们的程序进行保护是必要的，修改起来也很简单，给 channel send 加一个超时就可以了。

应用逻辑死锁，导致连接不可用，大量 goroutine 阻塞在 lock 上

大多数网络程序里，我们需要在发送应用层心跳，以保证在一些异常情况(比如拔网线)下，能够把那些无效连接从连接池里剔除掉。

对于我们的场景来说，客户端向外创建的连接，如果一直没有请求，那么每隔一段时间会向外发送一个应用心跳请求，如果心跳连续失败(超时) N 次，那么将该连接进行关闭。

在这个场景下会涉及到两把锁：

• 对连接进行操作的锁 conn lock
• 记录心跳请求的 request map lock

心跳成功的流程：收到心跳响应包，获取 conn lock -> 获取 request map lock 心跳失败的流程：timer 超时，获取 request map lock -> 需要关闭连接 -> 获取 conn lock

可以看出来，心跳的成功和失败流程并发时，获取锁的流程符合死锁的一般定义：持有锁、非抢占、循环等待。

这个 bug 比较难触发，因为心跳失败要失败 N 次才会关闭连接，而正好在最后一次发生了心跳成功和失败并发才会触发上述的死锁，线上可以通过 goroutine 短时间的上涨发现这个问题，goroutine 的现场也是可以看得到的。简单分析就可以发现这个死锁问题(因为后续的流程都会卡在其中一把锁上)。

知道原因解决起来就不麻烦了，涉及到一些具体的业务逻辑，这里就不赘述了。

CPU 尖刺问题

应用逻辑导致死循环问题

国际化业务涉及到冬夏令时的切换，从夏令时切换到冬令时，会将时钟向前拔一个月，但天级日志轮转时，会根据轮转前的时间计算 24 小时后的时间，并按与 24:00 的差值来进行 time.Sleep，这时会发现整个应用的 CPU 飚高。自动采样结果发现一直在循环计算时间和重命名文件。

list 一下相关的函数，能很快地发现执行死循环的代码位置。这里就不截真实代码了，随便举个例子：

        .          .     23:func cpuex(wr http.ResponseWriter, req *http.Request) {
         .          .     24: go func() {
    17.73s     19.37s     25:  for {
         .          .     26:  }
         .          .     27: }()
         .          .     28:}

参考资料

[1]

无人值守（上）: https://xargin.com/autodumper-for-go/

[2]

工具: https://github.com/mosn/holmes

[3]

这样: https://github.com/http-rs/async-h1/blob/main/src/server/decode.rs#L41