一、发现问题

  • 1、最近发现有一个Golang开发的API服务,每持续运行几天后就会阻塞,既不打印日志,API也无法访问。
  • 2、服务中包含API服务和几个定时执行的任务,任务也一样无法执行。
  • 3、服务中有访问视图的Route,却能访问。
  • 4、查看CPU、内存、文件句柄数等,都没发现异常。(这里推荐一个htop工具,CentOS可以通过yum install htop 安装)

二、解决问题

① 复现BUG

  • 首先如何复现BUG,只能让服务跑几天,出现bug才能检查。
  • 果不其然,今天BUG再次出现。

② 定位BUG

  • 1、能正常访问视图的Route,访问Route,产生的HTTP Log也能打印。
  • 2、Crontab Jobs 都无法执行,Log也无法打印。
  • 3、有一个打印第三方API状态的定时任务没有挂
  • 4、综上,是所有访问数据库的操作都阻塞了。那么应该从数据库操作查起。

③解决

由于我们用的是golang的gorm,我需要知道数据库的状态。那么我需要加入一个定时任务去打印一下数据库的状态。代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
func main (){
err := c.AddFunc("@every 5s", func() {
by, _ := json.Marshal(db.DB.DB().Stats())
log.Println(string(by))
})
if err != nil {
log.Fatalln(err.Error())
return
}
}

我们可以看到DBStats结构体是这样的,代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
// DBStats contains database statistics.
type DBStats struct {
MaxOpenConnections int // Maximum number of open connections to the database.
// Pool Status
OpenConnections int // The number of established connections both in use and idle.
InUse int // The number of connections currently in use.
Idle int // The number of idle connections.
// Counters
WaitCount int64 // The total number of connections waited for.
WaitDuration time.Duration // The total time blocked waiting for a new connection.
MaxIdleClosed int64 // The total number of connections closed due to SetMaxIdleConns.
MaxLifetimeClosed int64 // The total number of connections closed due to SetConnMaxLifetime.
}
  • 那么问题来了,加入定时任务打印数据库状态后,我发现InUse居然占满了,WaitCount也在不断增加。看下面的JSON数据:
1
2
3
4
5
{"MaxOpenConnections":30,"OpenConnections":30,"InUse":30,"Idle":0,"WaitCount":18032,"WaitDuration":66343149623,"MaxIdleClosed":0,"MaxLifetimeClosed":4203}
{"MaxOpenConnections":30,"OpenConnections":30,"InUse":30,"Idle":0,"WaitCount":179968,"WaitDuration":5069116627810,"MaxIdleClosed":0,"MaxLifetimeClosed":5147}
  • 那么基本可以确定问题了,大概就是从连接池里面取到连接,用完后没放回池子里面,或者是持续占用着连接。

  • 由于API和jobs里面都涉及到了数据库操作。那么什么样的操作会导致连接一直占用呢,我第一可能想到的就是Transaction没有Commit或者Rollback了。

  • 果不其然,找到了以下代码,那一刻真想打死自己~ 🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️🤦‍♂️

1
2
3
4
5
tx := o.Begin()
transactionIsOk, err := chain.EthChainInstance.GetTransactionReceipt(action.Hash)
if err != nil {
continue
}
  • 更改后的代码
1
2
3
4
5
6
7
tx := o.Begin()
transactionIsOk, err := chain.EthChainInstance.GetTransactionReceipt(action.Hash)
if err != nil {
tx.Rollback()
continue
}
  • 其实更建议的是用 defer tx.Commit() 或者 defer tx.Rollback()

  • 修复完后,重新构建部署后,观察了十来个小时,目前已经稳定运行了。

1
2
2019/05/08 00:18:11 {"MaxOpenConnections":300,"OpenConnections":13,"InUse":0,"Idle":13,"WaitCount":0,"WaitDuration":0,"MaxIdleClosed":0,"MaxLifetimeClosed":2804}
  • 由于Transaction没有结束,所以会一直占用着连接,导致InUse占满OpenConnections,并且使得其他的数据库操作在连接池里取得连接的时候,无法执行相应的SQL,一直阻塞着。
  • 完结~