记一次读写锁的排障过程
上午某个测试环境下的api服务器出现了异常，具体表现为对数据库的读写均挂起，查看日志，有报Too many connections的，有报Connection timeout的，于是怀疑程序的连接池内的连接数是否过多，于是查看了MySQL的连接状态，只有7个连接，不至于连接数不够用，很奇怪的问题。
通过程序堆栈信息来分析问题，发现大量的协程堵塞在读写锁的runtime_Semacquire中，还有很多的协程堵塞在网络读数据这儿。由于是读写锁，发现有1个写锁获得了锁内的互斥锁，有十多个写锁在等待互斥所的释放。
想了很久为什么会出现这种情况，后来自己写了个程序分析了一下，结果就豁然开朗了，下面看一下测试的函数：
func testCocurrencyMysqlOpt() {
var wg sync.WaitGroup
var mu sync.Mutex
cond := sync.NewCond(&mu)
const thdcnt = 1000
var cnt int64
done := false
db, _ := sql.Open("mysql", "root:password@tcp(10.100.47.4:3310)/?timeout=1s")
// db.SetMaxOpenConns(50)
for i := 0; i < thdcnt; i++ {
go func() {
var err error
wg.Add(1)
defer wg.Add(-1)
// Wait for signal
tid := atomic.AddInt64(&cnt, 1)
cond.L.Lock()
for !done {
cond.Wait()
}
cond.L.Unlock()
if nil != err {
log.Println("tid", tid, err)
return
}
if err = db.Ping(); nil != err {
log.Println("Ping error", err)
return
}
log.Println("tid", tid, "quit")
}()
}
go func() {
log.Println(http.ListenAndServe(":2333", nil))
}()
for {
if atomic.LoadInt64(&cnt) == thdcnt {
cond.L.Lock()
done = true
cond.Broadcast()
cond.L.Unlock()
break
}
time.Sleep(time.Second * 1)
}
wg.Wait()
}
这个函数很简单，同时创建1000个协程，然后给所有的协程发信号来操作数据库，执行结果是程序居然堵塞了，等很久也没有退出，下面来看看程序的堆栈信息：
goroutine profile: total 99
94 @ 0x430461 0x429a21 0x428fae 0x4a8bd5 0x4a9e8a 0x4ab586 0x531fa9 0x544e54 0x6fcc71 0x6fcfee 0x706c69 0x707787 0x7003f2 0x71470f 0x4fd937 0x4fc148 0x4fc34a 0x782024 0x45d7e1
# 0x428fad internal/poll.runtime_pollWait+0x5d D:/Go/src/runtime/netpoll.go:173
# 0x4a8bd4 internal/poll.(*pollDesc).wait+0xb4 D:/Go/src/internal/poll/fd_poll_runtime.go:85
# 0x4a9e89 internal/poll.(*ioSrv).ExecIO+0x139 D:/Go/src/internal/poll/fd_windows.go:205
# 0x4ab585 internal/poll.(*FD).Read+0x265 D:/Go/src/internal/poll/fd_windows.go:458
# 0x531fa8 net.(*netFD).Read+0x58 D:/Go/src/net/fd_windows.go:151
# 0x544e53 net.(*conn).Read+0x73 D:/Go/src/net/net.go:176
# 0x6fcc70 github.com/go-sql-driver/mysql.(*buffer).fill+0x130 D:/WorkSpace/Git/sql_proxy_git/confserver/src/github.com/go-sql-driver/mysql/buffer.go:68
# 0x6fcfed github.com/go-sql-driver/mysql.(*buffer).readNext+0xbd D:/WorkSpace/Git/sql_proxy_git/confserver/src/github.com/go-sql-driver/mysql/buffer.go:97
# 0x706c68 github.com/go-sql-driver/mysql.(*mysqlConn).readPacket+0x78 D:/WorkSpace/Git/sql_proxy_git/confserver/src/github.com/go-sql-driver/mysql/packets.go:31
# 0x707786 github.com/go-sql-driver/mysql.(*mysqlConn).readInitPacket+0x46 D:/WorkSpace/Git/sql_proxy_git/confserver/src/github.com/go-sql-driver/mysql/packets.go:137
# 0x7003f1 github.com/go-sql-driver/mysql.MySQLDriver.Open+0x2d1 D:/WorkSpace/Git/sql_proxy_git/confserver/src/github.com/go-sql-driver/mysql/driver.go:91
# 0x71470e github.com/go-sql-driver/mysql.(*MySQLDriver).Open+0x4e <autogenerated>:1
# 0x4fd936 database/sql.(*DB).conn+0x136 D:/Go/src/database/sql/sql.go:999
# 0x4fc147 database/sql.(*DB).PingContext+0x97 D:/Go/src/database/sql/sql.go:631
# 0x4fc349 database/sql.(*DB).Ping+0x49 D:/Go/src/database/sql/sql.go:649
# 0x782023 main.testCocurrencyMysqlOpt.func1+0x113 D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:951
1 @ 0x430461 0x429a21 0x428fae 0x4a8bd5 0x4a9e8a 0x4ab586 0x531fa9 0x544e54 0x67ff49 0x45d7e1
# 0x428fad internal/poll.runtime_pollWait+0x5d D:/Go/src/runtime/netpoll.go:173
# 0x4a8bd4 internal/poll.(*pollDesc).wait+0xb4 D:/Go/src/internal/poll/fd_poll_runtime.go:85
# 0x4a9e89 internal/poll.(*ioSrv).ExecIO+0x139 D:/Go/src/internal/poll/fd_windows.go:205
# 0x4ab585 internal/poll.(*FD).Read+0x265 D:/Go/src/internal/poll/fd_windows.go:458
# 0x531fa8 net.(*netFD).Read+0x58 D:/Go/src/net/fd_windows.go:151
# 0x544e53 net.(*conn).Read+0x73 D:/Go/src/net/net.go:176
# 0x67ff48 net/http.(*connReader).backgroundRead+0x68 D:/Go/src/net/http/server.go:660
1 @ 0x430461 0x429a21 0x428fae 0x4a8bd5 0x4a9e8a 0x4ad3be 0x4ad6b1 0x5325e8 0x54ccd5 0x54afd0 0x68adb6 0x6899e9 0x689720 0x68a8f6 0x7821f3 0x45d7e1
# 0x428fad internal/poll.runtime_pollWait+0x5d D:/Go/src/runtime/netpoll.go:173
# 0x4a8bd4 internal/poll.(*pollDesc).wait+0xb4 D:/Go/src/internal/poll/fd_poll_runtime.go:85
# 0x4a9e89 internal/poll.(*ioSrv).ExecIO+0x139 D:/Go/src/internal/poll/fd_windows.go:205
# 0x4ad3bd internal/poll.(*FD).acceptOne+0xad D:/Go/src/internal/poll/fd_windows.go:767
# 0x4ad6b0 internal/poll.(*FD).Accept+0x170 D:/Go/src/internal/poll/fd_windows.go:801
# 0x5325e7 net.(*netFD).accept+0x87 D:/Go/src/net/fd_windows.go:192
# 0x54ccd4 net.(*TCPListener).accept+0x34 D:/Go/src/net/tcpsock_posix.go:136
# 0x54afcf net.(*TCPListener).AcceptTCP+0x4f D:/Go/src/net/tcpsock.go:234
# 0x68adb5 net/http.tcpKeepAliveListener.Accept+0x35 D:/Go/src/net/http/server.go:3120
# 0x6899e8 net/http.(*Server).Serve+0x1b8 D:/Go/src/net/http/server.go:2695
# 0x68971f net/http.(*Server).ListenAndServe+0xaf D:/Go/src/net/http/server.go:2636
# 0x68a8f5 net/http.ListenAndServe+0x85 D:/Go/src/net/http/server.go:2882
# 0x7821f2 main.testCocurrencyMysqlOpt.func2+0x52 D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:960
1 @ 0x430461 0x430555 0x4048e2 0x4045bb 0x4fd2ba 0x45d7e1
# 0x4fd2b9 database/sql.(*DB).connectionOpener+0x59 D:/Go/src/database/sql/sql.go:871
1 @ 0x430461 0x430555 0x441992 0x441560 0x4746d9 0x781ea4 0x781ef7 0x42ffc2 0x45d7e1
# 0x44155f sync.runtime_Semacquire+0x3f D:/Go/src/runtime/sema.go:56
# 0x4746d8 sync.(*WaitGroup).Wait+0x78 D:/Go/src/sync/waitgroup.go:131
# 0x781ea3 main.testCocurrencyMysqlOpt+0x1f3 D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:973
# 0x781ef6 main.main+0x26 D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:977
# 0x42ffc1 runtime.main+0x221 D:/Go/src/runtime/proc.go:195
1 @ 0x778a19 0x778807 0x775322 0x78170f 0x781a12 0x6869bb 0x6880d7 0x68963b 0x685854 0x45d7e1
# 0x778a18 runtime/pprof.writeRuntimeProfile+0xa8 D:/Go/src/runtime/pprof/pprof.go:637
# 0x778806 runtime/pprof.writeGoroutine+0xa6 D:/Go/src/runtime/pprof/pprof.go:599
# 0x775321 runtime/pprof.(*Profile).WriteTo+0x3b1 D:/Go/src/runtime/pprof/pprof.go:310
# 0x78170e net/http/pprof.handler.ServeHTTP+0x1be D:/Go/src/net/http/pprof/pprof.go:237
# 0x781a11 net/http/pprof.Index+0x1e1 D:/Go/src/net/http/pprof/pprof.go:248
# 0x6869ba net/http.HandlerFunc.ServeHTTP+0x4a D:/Go/src/net/http/server.go:1918
# 0x6880d6 net/http.(*ServeMux).ServeHTTP+0x136 D:/Go/src/net/http/server.go:2254
# 0x68963a net/http.serverHandler.ServeHTTP+0xba D:/Go/src/net/http/server.go:2619
# 0x685853 net/http.(*conn).serve+0x723 D:/Go/src/net/http/server.go:1801
我们发现大量的协程堵塞在了runtime_pollWait中，这样我们就明白了，我们的连接池没有限制最大连接数，导致连接数过多，有些连接会被MySQL拒绝掉，那么我们这里直接有响应，但是有一部分一直堵塞在了读取初始包这儿，导致了程序整体的堵塞。
有了这个，那么分析这个问题就很清晰了。某个时间段，大量的读请求进来，导致连接池大量的创建新的连接，有一部分的连接没有创建成功，进入堵塞状态，但是读请求会先持有读写锁，于是无数的读请求挂起。这时候凑巧有几个写请求过来，这时候写锁发现有多个读锁持有了读写锁，那么会挂起等待。后续还会有读请求过来，但是由于已经有写锁在等待了，写锁无法获得锁，于是也挂起等待。于是就变成了多个持有写锁的协程堵塞在读取MySQL的回包中，1个写请求获得了写锁，多个写请求等待写锁，多个写请求堆积等待写锁获得读写锁。
当堵塞的读请求全部超时后，那么最后一个读请求会唤醒被挂起的写请求，写请求执行完操作后，释放读写锁，这时候，几个写请求，N多堆积的读请求又会来争用读写锁，这又回到了一开始的场景，于是一直循环，直到读请求不堆积了，或者没有写请求了，这才会恢复。
造成这种异常的原因，一个是没有个连接池设定最大连接数，还有一个是测试环境的MySQL的参数太低。但是程序这儿总得解决，最简单的方法就是给连接池设定最大连接数。把上面注释掉的代码加进去，整个程序就恢复正常了。这个也算自己的一个疏漏吧。
共 0 条回复
暂时没有人回复哦，赶紧抢沙发
发表新回复
作者
