记一次Beego高并发下踩坑过程

随着618的到来,业务的QPS也在不断递增,线上业务也暴漏出来了一些以前没有遇到过的问题,好在经过不断的排查之后终于找到问题的主因了,这里记录一下本次踩坑的详细过程。

Part1: 日志报错:goroutine select

172-16-61-151 goroutine 474911 [select]:
172-16-61-151   /usr/local/go1.10.3/go/src/runtime/netpoll.go:173 +0x57
172-16-61-151 goroutine 506699 [select]:
172-16-61-151 goroutine 506270 [select]:
172-16-61-151 internal/poll.(*FD).Read(0xc47f752480, 0xc450ea7061, 0x1, 0x1, 0x0, 0x0, 0x0)
172-16-61-151   /usr/local/go1.10.3/go/src/net/http/transport.go:1238 +0x97f
172-16-61-151   /usr/local/go1.10.3/go/src/net/http/transport.go:1237 +0x95a

出现这个错误实在令人摸不着头绪,正常情况下是不应该出现这种底层异常的,而且由于日志数量太多,很难查找到堆栈的报错源头。在stackoverflow上得知,golang官方说出现这种错误是可以忽略的,因为你无法定位到具体的异常原因,真正的主因并不在这里,你需要从业务逻辑上去检查引发这种错误的源头。

Part2: 日志报错:goroutine io wait

172-16-61-150 goroutine 38657 [IO wait]:
172-16-61-150 internal/poll.runtime_pollWait(0x7fe47807fb88, 0x72, 0xc4733099a8)
172-16-61-150   /usr/local/go1.10.3/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
172-16-61-150 net.(*conn).Read(0xc4224f0188, 0xc466ce5000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
172-16-61-150   /usr/local/go1.10.3/go/src/bufio/bufio.go:100 +0x11e
172-16-61-150 created by net/http.(*Transport).dialConn
172-16-61-150   /usr/local/go1.10.3/go/src/net/http/transport.go:1238 +0x97f
172-16-61-150 internal/poll.(*pollDesc).wait(0xc467774298, 0x72, 0xffffffffffffff00, 0xd8b9e0, 0x1187740)
172-16-61-150   /usr/local/go1.10.3/go/src/net/http/transport.go:1238 +0x97f
172-16-61-150   /usr/local/go1.10.3/go/src/net/http/client.go:322 +0x2ac
172-16-61-150   /usr/local/go1.10.3/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
172-16-61-150 net.(*netFD).Read(0xc4661fef80, 0xc466ce5000, 0x1000, 0x1000, 0x456140, 0xc47d343980, 0x4)
172-16-61-150   /usr/local/go1.10.3/go/src/net/http/transport.go:1453 +0x136
172-16-61-150 net/http.(*persistConn).readLoop(0xc467b4c5a0)
172-16-61-150 internal/poll.runtime_pollWait(0x7fe4b82bfaa0, 0x72, 0xc47330a9a8)
172-16-61-150   /usr/local/go1.10.3/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
172-16-61-150 internal/poll.(*pollDesc).waitRead(0xc467774298, 0xc46822c000, 0x1000, 0x1000)
172-16-61-150   /usr/local/go1.10.3/go/src/net/fd_unix.go:202 +0x4f
172-16-61-150 bufio.(*Reader).fill(0xc47cb9ac60)
172-16-61-150   /usr/local/go1.10.3/go/src/net/http/transport.go:1601 +0x185
172-16-61-150   /usr/local/go1.10.3/go/src/runtime/netpoll.go:173 +0x57

怀疑:起初经过网上的不断搜索,有怀疑出现该异常是因为当前有太多的http request挂着,没有处理完才引发的这种问题 反驳:如果goroutine太多,一定会引发too many open files,而日志中无法找到相应的字眼,故排除,每个容器的goroutine数量占据4k左右的内存,理论上只要内存足够大,是可以开无限个协程的。

怀疑:web服务请求QPS上涨后很多一直挂着的请求,一直在serverWrite中。 反驳:加入了serverReadTimeoutserverWriteTimeout,无好转,且业务延时很低,可以排除是此原因。

Part3:日志报错:locked to thread

goroutine running on other thread; stack unavailable
goroutine 75 [select, 35 minutes, locked to thread]:

这次似乎越来越接近引发崩溃的源头了,出现这个问题的原因主要是一个goroutine无法访问本来属于他的stack空间,既然数据已经访问不到了,那么这个协程也就无法继续跑下去了,关于协程的GMP模型,以及内部的epoll网络IO复用过程,都可以在源码中的runtime包下面找到,这里先不做详细介绍。但是看到这里,仍然无法判断出到底是什么原因导致了这种runtime异常。

Part4:真正主因

最后,只能在日志里边搜一些比较显眼的关键字了,比如我这里搜了一个fatal error,看过runtime这个包代码的可以知道,底层runtime会log出来一些错误,这些错误已经到了不可挽回的地步,此时就会打印出一些fatal级别的error日志,终于,找到了如下日志:

fatal error: concurrent map read and map write

这里已经很明显,可以直接定位到程序崩溃的主因了,原因就是并发下对map数据的同时读和写! 然而改了项目一波又一波之后仍然出现该错误

最后发现是beego的问题!!!
最后发现是beego的问题!!!
最后发现是beego的问题!!!

目前已经在github上提出了 https://github.com/astaxie/beego/issues/3686

Part5:解决方法

  1. 使用sync.Map
  2. 使用sync.Mutex对代码行加锁
  3. 放弃使用beego自带的参数解析方法

Part6:总结

  1. runtime打印出来的goroutine堆栈信息本身不是报错信息,而是当runtime异常发生时,会打印出来当前协程的一些工作情况。
  2. 类似于偏底层epoll这种广泛使用的网络IO复用模型,一般不会出现这个错误,即使出现这个错误也应该是外部环境的因素。
  3. 很多不起眼的问题会在高并发下被无限放大,比如数据安全问题,连接资源问题,数据库瓶颈问题等等。
赞赏我吗