V200，找大佬帮忙看个 BUG，不够我加钱

V2EX = way to explore

V2EX 是一个关于分享和探索的地方

现在注册

已注册用户请登录

The Go Programming Language

› http://golang.org/

› Go Playground

Go Projects

› Revel Web Framework

这是一个创建于 776 天前的主题，其中的信息可能已经有所发展或是发生改变。

由于找不到具体问题在哪，没办法去对应的社区提问，因此我就只能发这里了，希望有划水路过的大佬帮忙看看，能帮忙解决的话就当我请大佬吃个海底捞。

背景：go 语言写的 http 服务，程序偶然出现无响应（ Stop The World 那种无响应），进而导致 Tcp Socket 句柄文件不释放，进而服务器文件句柄数疯涨。故障复现方法未知，可能一周左右出现一次，也可能一个月都不出现。线上 2 个机房，均有发生，发生时都是单机，没有大量出现，重启服务后恢复

PS:目前配置了 ping 接口探活+自动摘流重启。大概最近半年就出现了十次左右，都自动重启恢复了，但是本着探索的精神，还是想找到问题根源

环境：centos7.2+golang1.18.3

调试过程：

1 、监控发现服务异常，文件句柄异常，第一反应是代码问题，没有执行 close 函数导致。但是仔细一想，我 tm 这是 go 项目啊，又不是 c 语言项目，go 项目用的 net.http 包启动的 http 服务，又不是我手动管理的 tcp ，哪特么来的 close 啊。

2 、怀疑是项目其他地方有什么 api 调用，没有关闭连接，排查了很久，并没有发现问题。

3 、发现程序出问题这段时间，连日志都不输出了，程序 debug 接口也挂了（和业务接口不是同一个端口，debug 接口本来用于监控程序 gc 、协程数量等信息的）。开始怀疑不是 close 的问题。

4 、在程序主逻辑启动前，加了一段测试代码，代码如下

go func() {
    for {
        time.Sleep(1 * time.Minute)
        fmt.Println("Hello World!")
    }
}()

讲道理，这应该不受任何逻辑影响，始终都该输出吧。加上这段代码，重新发布项目，等了半个月，终于又出问题了。上服务器一看，出问题的时候，这个 HelloWorld 也不输出了。

5 、由于程序完全没响应，任何逻辑都不执行，因此从线上把故障机器摘流，然后使用 dlv 注入进程进行调试。结果如下：

（ 1 ）、协程总数异常，此时有 5w+个协程，正常情况应该不超过 500 个协程

（ 2 ）、大量协程被死锁，都是卡在同一个地方 Goroutine 19024799 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684384197s]

（ 3 ）、查看死锁协程的调用栈，结果与业务代码无关

 0  0x000000000043a556 in runtime.gopark
    at /usr/local/go1.18.3/src/runtime/proc.go:362
 1  0x000000000044b0b3 in runtime.goparkunlock
    at /usr/local/go1.18.3/src/runtime/proc.go:367
 2  0x000000000044b0b3 in runtime.semacquire1
    at /usr/local/go1.18.3/src/runtime/sema.go:144
 3  0x00000000004665a5 in sync.runtime_SemacquireMutex
    at /usr/local/go1.18.3/src/runtime/sema.go:71
 4  0x0000000000473785 in sync.(*Mutex).lockSlow
    at /usr/local/go1.18.3/src/sync/mutex.go:162
 5  0x00000000004740bf in sync.(*Mutex).Lock
    at /usr/local/go1.18.3/src/sync/mutex.go:81
 6  0x00000000004740bf in sync.(*Pool).pinSlow
    at /usr/local/go1.18.3/src/sync/pool.go:213
 7  0x000000000047400e in sync.(*Pool).pin
    at /usr/local/go1.18.3/src/sync/pool.go:206
 8  0x0000000000473d45 in sync.(*Pool).Get
    at /usr/local/go1.18.3/src/sync/pool.go:128
 9  0x0000000000711e29 in net/http.newTextprotoReader
    at /usr/local/go1.18.3/src/net/http/request.go:994
10  0x0000000000711fd9 in net/http.readRequest
    at /usr/local/go1.18.3/src/net/http/request.go:1024
11  0x00000000007181ea in net/http.(*conn).readRequest
    at /usr/local/go1.18.3/src/net/http/server.go:988
12  0x000000000071c58b in net/http.(*conn).serve
    at /usr/local/go1.18.3/src/net/http/server.go:1891
13  0x0000000000721cce in net/http.(*Server).Serve.func3
    at /usr/local/go1.18.3/src/net/http/server.go:3071
14  0x000000000046a641 in runtime.goexit
    at /usr/local/go1.18.3/src/runtime/asm_amd64.s:1571

6 、到这来我已经不知道该怎么继续排查了，服务器网络 io 、磁盘 io 、cpu 、内存等待均无明显异常。

7 、找运维在网关上面录制了流量，故障前一分钟都没发现异常流量，应该不存在被攻击的问题

8 、哪位大佬能给分析下呢，顺便给小弟讲解讲解，为啥我那个 HelloWorld 日志也不输出了？

下面附上完整的 dlv grs 结果（部分包名、路径打码了）：

(dlv) grs
  Goroutine 1 - User: /home/xxxxxx/golibs/rpcserver/[email protected]/rpcserver/server.go:392 xxxx/golibs/rpcserver/v2/rpcserver.(*Server).waitHttp (0xd0c588) [select 452427h39m57.846100461s]
  Goroutine 2 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [force gc (idle) 452385h49m20.252083363s]
  Goroutine 3 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [finalizer wait 452427h39m57.869422736s]
  Goroutine 4 - User: /home/xxxxxx/devops/[email protected]/client_golang/statsdlib/push.go:39 xxxxxx/devops/statsd/client_golang/statsdlib.statsdPushLoop (0x87b17e) [chan receive]
  Goroutine 9 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 10 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 15 - User: /home/xxxxxx/xxxxxx/gobiz/[email protected]/file.go:309 xxxxxx/gobiz/logger.(*fileLog).writeLoop (0x80a545) [select 452427h39m57.846215549s]
  Goroutine 16 - User: /home/xxxxxx/xxxxxx/rpc/[email protected]/rpc/common/watcher.go:49 xxxxxx/rpc/rpc-go-spl-v2/rpc/common.(*DirWatcher).run.func1 (0x84a9f9) [chan receive]
  Goroutine 18 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC sweep wait]
  Goroutine 19 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC scavenge wait]
  Goroutine 27 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 28 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 29 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 30 - User: /home/xxxxxx/xxxxxx/platform-ha/onekey-degrade_sdk_go/[email protected]/degrade/metric.go:96 xxxxxx/platform-ha/onekey-degrade_sdk_go/v3/degrade.(*metricSender).sendMetricFromChan (0xb05e65) [chan receive 452427h39m57.86959434s]
  Goroutine 31 - User: /home/xxxxxx/xxxxxx/platform-ha/onekey-degrade_sdk_go/[email protected]/degrade/metric.go:96 xxxxxx/platform-ha/onekey-degrade_sdk_go/v3/degrade.(*metricSender).sendMetricFromChan (0xb05e65) [chan receive 452427h39m57.869609575s]
  Goroutine 34 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.683989625s]
  Goroutine 35 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684006698s]
  Goroutine 36 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684023352s]
  Goroutine 37 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684037091s]
  Goroutine 38 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684051841s]
  Goroutine 39 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684066197s]
  Goroutine 40 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684082165s]
  Goroutine 41 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684095326s]
  Goroutine 42 - User: /home/xxxxxx/xxxxxx/xxxx/golibs/[email protected]/metrics.go:280 xxxxxx/xxxx/golibs/metrics.(*Sender).asyncSendLoop.func1 (0x880a5b) [select 452391h19m51.199497773s]
  Goroutine 43 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.68413238s]
  Goroutine 45 - User: /usr/local/go1.18.3/src/runtime/time.go:194 time.Sleep (0x46742e) [sleep]
  Goroutine 46 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.8518662s]
  Goroutine 48 - User: /gaia/workspace-job/xxxxxx/xxxxx/common/handlers/apollo/apollo.go:50 xxxxx/common/handlers/apollo.OnConfigUpdate.func1 (0x884859) [chan receive 452427h39m57.863062571s]
  Goroutine 49 - User: /gaia/workspace-job/xxxxxx/xxxxx/common/handlers/apollo/apollo.go:50 xxxxx/common/handlers/apollo.OnConfigUpdate.func1 (0x884859) [chan receive 452427h39m57.846560172s]
  Goroutine 67 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 68 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 69 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [GC worker (idle)]
  Goroutine 72 - User: /home/xxxxxx/github.com/getsentry/[email protected]/transport.go:378 github.com/getsentry/sentry-go.(*HTTPTransport).worker (0x8010ec) [chan receive 452391h19m51.973327187s]
  Goroutine 73 - User: /home/xxxxxx/xxxxxx/rpc/[email protected]/rpc/common/watcher.go:49 xxxxxx/rpc/rpc-go-spl-v2/rpc/common.(*DirWatcher).run.func1 (0x84a9f9) [chan receive]
  Goroutine 75 - User: /usr/local/go1.18.3/src/database/sql/sql.go:1226 database/sql.(*DB).connectionOpener (0xa3d38d) [select 452427h39m57.863183594s]
  Goroutine 84 - User: /usr/local/go1.18.3/src/runtime/sigqueue.go:151 os/signal.signal_recv (0x466bef) (thread 1238)
  Goroutine 98 - User: /usr/local/go1.18.3/src/net/fd_unix.go:172 net.(*netFD).accept (0x522b15) [IO wait]
  Goroutine 99 - User: /usr/local/go1.18.3/src/net/fd_unix.go:172 net.(*netFD).accept (0x522b15) [IO wait 452427h39m57.846699823s]
  Goroutine 100 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684348233s]
  Goroutine 101 - User: /usr/local/go1.18.3/src/net/fd_unix.go:172 net.(*netFD).accept (0x522b15) [IO wait]
  Goroutine 102 - User: /usr/local/go1.18.3/src/runtime/proc.go:362 runtime.gopark (0x43a556) [select 452427h39m57.846735781s]
* Goroutine 19024799 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684384197s]
  Goroutine 19168258 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684396903s]
  Goroutine 19913951 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684409102s]
  Goroutine 19958391 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684421539s]
  Goroutine 20081541 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684433615s]
  Goroutine 20116495 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.684446142s]
  Goroutine 20172239 - User: /usr/local/go1.18.3/src/runtime/sema.go:71 sync.runtime_SemacquireMutex (0x4665a5) [semacquire 452391h19m50.68446185s]
  ......(后面都是重复的，就省略了)

28 条回复 • 2022-11-01 17:25:48 +08:00

zhanglintc

2022-10-27 23:53:34 +08:00

不是很懂，随便回复一下，万一胡言乱语能有所启发呢。

> 大量协程被死锁

一路看下来，原因就是死锁了呗，协程太多，资源耗尽，彻底卡死了吧。
先从代码里有可能用到锁啊什么地方开始下手？

如果实在不是自己代码的问题，那就考虑是不是 go 的 bug 了？

xyjincan

2022-10-28 07:54:50 +08:00 via Android

考虑设备有硬件问题呢

saberlong

2022-10-28 08:32:38 +08:00 via Android

看到 p.pinSlow 。猜测是 sync.Pool 这的问题。可能是 sync.Pool 使用有误，大量新建 sync.Pool 和销毁。sync.Pool 有个全局维护的数组 allPools ，有个全局的锁保证它的并发读写。

saberlong

2022-10-28 08:35:09 +08:00 via Android

再看 request ，猜测是不是有业务在做 http 请求时，每次都新建 http.Client 后请求。这样导致 sync.Pool 每次都重新创建

hopingtop

2022-10-28 10:16:05 +08:00

首先你的 go hello word 没有被打印，就相当于调度器就开始没有绑定你这个任务执行了，或者说调度器被其他的 goroutine 完全占用了。占用的情况大一些
第二个，你重点看一下代 loop 的函数，比如 logger.writeLoop 和 metrics.asyncSendLoop 特别是后者，是否出现了，因为函数名是异步 async 开头，这里是否是开启了大量的 goroutine 然后没有正确的被释放，导致 goroutine 常驻。

先看看我说的上面这两个地方呢

hopingtop

2022-10-28 10:21:09 +08:00

但是按理来说 5W 的 goroutine 小 case ，

hopingtop

2022-10-28 10:22:37 +08:00

@hopingtop 但是如果这些 goroutine 里面有大量的锁，那可很可能造成你当前这样现象。

Zach369

2022-10-28 10:58:04 +08:00

应该是你代码出问题了. 使用 pprof 看看

brucemaclin

2022-10-28 11:22:52 +08:00

看着是死锁了 trace 或者 pprof 看看

sadfQED2

2022-10-28 11:41:49 +08:00

@Zach369 #8
@brucemaclin #9 我上面说程序 debug 接口也挂了，我们那个 debug 接口就是 pprof 接口，挂了以后 pprof 也看不到了

sadfQED2

2022-10-28 11:53:30 +08:00

@hopingtop #5 asyncSendLoop 里面确实有启 goroutine ，不过这是第三方包的代码，我先研究下这个代码是啥逻辑。顺便问一下，为什么 goroutine 里面有锁会影响其他 goroutine 执行呢，不是说 golang 已经实现抢占式调度了吗，那我 HelloWorld 日志那个协程为啥抢不到调度资源呢

hopingtop

2022-10-28 12:38:05 +08:00

@sadfQED2 无用的 goroutine 如果太多，大家都在抢，你怎么能保证你的 helloWorld 能抢到。当然具体的我也无法从上面的信息看出太多，如果这个第三方代码是开源的，可以贴一下 github 我可以去定位一下相关的实现

runningman

2022-10-28 12:43:02 +08:00

这种东西，得看代码，分析，打日志等。不是描述一下就能搞定的

alexsunxl

2022-10-28 12:52:21 +08:00

这个问题是累积时间出现，但时间不固定（大致 2 周）。应该是某个角落逻辑有死锁锁住了协程。

sadfQED2

2022-10-28 12:58:10 +08:00 via Android

@hopingtop 内部的，没有开源。

大家都在抢的话，理论上是不是时间够久，总能抢到，但是我观察了一天，好像都没输出

hopingtop

2022-10-28 14:17:20 +08:00

@sadfQED2 不能这么说，何况还是 1/5W 的概率，只要不是 100% 必执行，你等一天或者 N 天都可能没得结果。所以还是要先看代码，就从我说的那个方面先排查了来吧。
这种问题，不看代码和断点，确实不能给出更多的回复了。

sadfQED2

2022-10-28 14:26:17 +08:00

https://gist.github.com/Jinnrry/d11a8c7dc74da724832206749afa12d8

asyncSendLoop 的代码，看起来是维护了一个 Loop ，一直读 chan 数据，应该也只起了一个 GoRoutine ，然后执行计数函数，计数内部逻辑没看明白，但是应该是本地操作

@hopingtop

Y9qn1d

2022-10-28 15:43:19 +08:00 via iPhone

应该不是死锁，而是死循环，很多 goroutine 卡在 for 里会导致 hello world 打不出来

yongbozou

2022-10-28 16:08:15 +08:00

https://cs.opensource.google/go/go/+/refs/tags/go1.18.3:src/sync/pool.go;l=213

能看下 5w 个 goroutinues 卡住的应该有两种类型：
1. 第一种是 allPoolsMu.Lock() 卡住了。
2. 第二种就是持有锁的那个 goroutine 了，可以搜下 pinSlow 所有的 gouroutine ，是否有不同于 allPoolsMu.Lock() 的。再顺着这个 goroutine ，看它为什么卡住

func (p *Pool) pinSlow() (*poolLocal, int) {
// Retry under the mutex.
// Can not lock the mutex while pinned.
runtime_procUnpin()
allPoolsMu.Lock()
defer allPoolsMu.Unlock()
pid := runtime_procPin()
// poolCleanup won't be called while we are pinned.
s := p.localSize
l := p.local
if uintptr(pid) < s {
return indexLocal(l, pid), pid
}
if p.local == nil {
allPools = append(allPools, p)
}
// If GOMAXPROCS changes between GCs, we re-allocate the array and lose the old one.
size := runtime.GOMAXPROCS(0)
local := make([]poolLocal, size)
atomic.StorePointer(&p.local, unsafe.Pointer(&local[0])) // store-release
runtime_StoreReluintptr(&p.localSize, uintptr(size)) // store-release
return &local[pid], pid
}

yongbozou

2022-10-28 16:10:37 +08:00

http 库里面有个 sync.Pool 来复用 textproto.Reader ，减少 gc 。

hopingtop

2022-10-28 16:38:18 +08:00

当前你贴的代码，确实没得什么问题，asyncSendMetricLoop 这个方法调用，只会有一次吗？是 sync.Once 吗？
Counter 里面会涉及到锁的问题吗？
asyncSendMetricLoop 因为 metricCell chan 不关闭，这个 goroutine 就会常驻，所以这个方法如何使用就很关键。

hopingtop

2022-10-28 16:39:18 +08:00

最终也并不一定这里有问题，这只是一个排查方向 @sadfQED2

yougg

2022-10-28 17:50:38 +08:00

如果 debug 接口挂起抓不到 pprof, 就把启动进程的标准和错误输出重定向到文件, 服务 hang 住的时候 kill -3 <pid>来查看输出重定向文件中的 goroutine 栈信息.

alphayan

2022-10-30 19:07:30 +08:00

私聊

Jhon11

2022-10-31 09:05:38 +08:00

看看 lock 和 unlock 是不是都有释放，还有就是一个 lock 后面代码，看看是不是有死循环了

bugfan

2022-10-31 09:19:14 +08:00

卧槽，前段时间我的一个在线上运行的服务出现了和 op 很相似的情况。。。最后发现是 goroutine 太多了（另外我的服务器配置也是非常 mini 的那种），我改了改代码，现在已经不出现了。
原本我是在 443 端口上面接收 tcp 流量，如果发现包里面有 sni 会校验权限，如果匹配会做 sni 代理，否则会把流量发到 https server ，这期间很多地方的逻辑用了 goroutinte 并发实现。我最后把 sni 代理去掉了，443 端口的流量直接用 http handerl 处理，就再也没复线了。
怀疑 op 也是类似情况，程序无响应的时候，我从云平台看到内存几乎占满了，磁盘 io 也非常大，大量野 goroutine 导致内存增长

lysS

2022-11-01 09:44:54 +08:00

你这个 stw 了，内存、cpu 又正常；我感觉是 go 中调度的一个 bug 。要是能稳定复现就好了

DevKuan

2022-11-01 17:25:48 +08:00

goroutine 太多就容易出问题，要用 context 控制