Castle

我的沉思、笔记和回忆

TarsGo 启动时出现多个进程问题的排查

技术

现象

同一个服务有多个进程。

image.png

排查过程

strace

通过 strace 命令发现,除了时钟调用以外,就是 futex 调用,说明系统在等待锁的释放。

我们发现这种情况发生在平滑重启以后,因此之前认为是老的进程没有退出导致的。

47de4fe8-54b1-4e08-aa77-5a91363e2a97.png

dlv

通过 dlv attach 6164 命令,进入 dlv 控制台。

输入 grs,列出所有的 goroutines。

2dab6a01-66d6-4d1b-895d-06e1ca4d2111.png

我们发现有很多的 goroutines, goroutine 1 是 main goroutine,可以简单理解为通过 main.main 启动了程序,派生出了其他的 goroutine。

我们切换到 goroutine 1 来查看堆栈信息,看下发生了什么。

运行命令 gr 1,切换到 goroutine 1。

运行命令 bt,查看堆栈信息。

a34b75e6-25c5-498d-ad3b-ea5f57d8892c.png

我们发现程序阻塞在了 statf.go:125,我们通过输入 c 命令,让程序继续运行,发现程序继续锁死,无法继续。

82d6ba14-1ad6-45cb-906f-69ccb12382c1.png

判断确实是在这里卡死了程序,我们看下这一行代码:

func (s *StatFHelper) pushBackMsg(stStatInfo StatInfo, fromServer bool) {
    if fromServer {
        s.chStatInfoFromServer <- stStatInfo
    } else {
        s.chStatInfo <- stStatInfo // 程序卡在了这里
    }
}

6d7408a6-cea1-4a48-8a46-1c7a9e8bc8cd.png

结合前边 grs 命令的结果,我们发现这里的 s.chStatInfo 是 nil,所以程序卡死在了这里。

e01e8ad2-28ff-454b-a6d0-02895233b871.png

如果 StatReport 是 nil,则程序不会进入到上报这一行,因此,StatReport 有值,但是 StatReport.chStatInfo 是 nil 才可能出现这种情况。

我们看下 StatReport 的初始化:

5b26b91b-5d98-47a4-bbdd-2c6ce6bb4d0e.png

146 行 StatReport 进行了初始化,147 行进行了 StatReport.chStatInfo 的赋值,如果 goroutine 在 146 行以后进行了切换,就有可能造成上述情况的发生。

为什么会出现这种情况?

我们来看下 StatReport 的整个初始化过程:

596e3f9d-420f-4fd9-b0a3-c4a0ca6edf30.png

可以发现,StatReport 的初始化另外单独启动了一个 goroutine,而非同步进行的。

当我们初始化配置的时候,需要调用 tars 的 config 服务获取配置,而每个 tars 请求,都会调用 StatReport.pushBackMsg 来上报此次请求是否成功。

当我们调用了 tars 时,刚好发生了 StatReport 未完全初始化,导致了程序卡死在这里,无法继续运行,但是因为不是所有的 goroutine 都停掉了,因此 go 程序不会 panic(如果所有的 goroutine 都阻塞了,go 程序会 panic)。

通过对多个服务的观察,我们发现这些服务的现象是相同的,都是卡在了上报状态过程中。

如何解决?

知道了上述问题产生的原因,解决起来就很简单了。

  1. 我们可以通过同步初始化而非异步初始化的方式解决问题。
  2. 初始化 StatReport 的时候一次完成,即 StatReport 要么为 nil,要么 StatReport 有值时 StatReport.chStatInfo 也已经有值
  3. 在 s.chStatInfo <- stStatInfo 加上 select default 的方式避免程序锁住。

本人在社区群反馈后,TarsGo 官方已经在 https://github.com/TarsCloud/TarsGo/pull/505 这次 PR 中进行了该问题的修复。

创建于2024年01月09日 14:27
阅读量 3
留言列表

暂时没有留言

添加留言