• 首页
  • 分类
  • golang
  • 记一次读写锁的排障过程

    • 记一次读写锁的排障过程

    由 sryan 在 2018-08-01 15:35 发布

    记一次读写锁的排障过程

    上午某个测试环境下的api服务器出现了异常，具体表现为对数据库的读写均挂起，查看日志，有报Too many connections的，有报Connection timeout的，于是怀疑程序的连接池内的连接数是否过多，于是查看了MySQL的连接状态，只有7个连接，不至于连接数不够用，很奇怪的问题。

    通过程序堆栈信息来分析问题，发现大量的协程堵塞在读写锁的runtime_Semacquire中，还有很多的协程堵塞在网络读数据这儿。由于是读写锁，发现有1个写锁获得了锁内的互斥锁，有十多个写锁在等待互斥所的释放。

    想了很久为什么会出现这种情况，后来自己写了个程序分析了一下，结果就豁然开朗了，下面看一下测试的函数：

    1. func testCocurrencyMysqlOpt() {
    2.     var wg sync.WaitGroup
    3.     var mu sync.Mutex
    4.     cond := sync.NewCond(&mu)
    5.     const thdcnt = 1000
    6.     var cnt int64
    7.     done := false
    9.     db, _ := sql.Open("mysql", "root:password@tcp(10.100.47.4:3310)/?timeout=1s")
    10.     // db.SetMaxOpenConns(50)
    12.     for i := 0; i < thdcnt; i++ {
    13.         go func() {
    14.             var err error
    15.             wg.Add(1)
    16.             defer wg.Add(-1)
    17.             // Wait for signal
    18.             tid := atomic.AddInt64(&cnt, 1)
    19.             cond.L.Lock()
    20.             for !done {
    21.                 cond.Wait()
    22.             }
    23.             cond.L.Unlock()
    25.             if nil != err {
    26.                 log.Println("tid", tid, err)
    27.                 return
    28.             }
    29.             if err = db.Ping(); nil != err {
    30.                 log.Println("Ping error", err)
    31.                 return
    32.             }
    33.             log.Println("tid", tid, "quit")
    34.         }()
    35.     }
    37.     go func() {
    38.         log.Println(http.ListenAndServe(":2333", nil))
    39.     }()
    41.     for {
    42.         if atomic.LoadInt64(&cnt) == thdcnt {
    43.             cond.L.Lock()
    44.             done = true
    45.             cond.Broadcast()
    46.             cond.L.Unlock()
    47.             break
    48.         }
    49.         time.Sleep(time.Second * 1)
    50.     }
    51.     wg.Wait()
    52. }

    这个函数很简单，同时创建1000个协程，然后给所有的协程发信号来操作数据库，执行结果是程序居然堵塞了，等很久也没有退出，下面来看看程序的堆栈信息：

    1. goroutine profile: total 99
    2. 94 @ 0x430461 0x429a21 0x428fae 0x4a8bd5 0x4a9e8a 0x4ab586 0x531fa9 0x544e54 0x6fcc71 0x6fcfee 0x706c69 0x707787 0x7003f2 0x71470f 0x4fd937 0x4fc148 0x4fc34a 0x782024 0x45d7e1
    3. #    0x428fad    internal/poll.runtime_pollWait+0x5d                D:/Go/src/runtime/netpoll.go:173
    4. #    0x4a8bd4    internal/poll.(*pollDesc).wait+0xb4                D:/Go/src/internal/poll/fd_poll_runtime.go:85
    5. #    0x4a9e89    internal/poll.(*ioSrv).ExecIO+0x139                D:/Go/src/internal/poll/fd_windows.go:205
    6. #    0x4ab585    internal/poll.(*FD).Read+0x265                    D:/Go/src/internal/poll/fd_windows.go:458
    7. #    0x531fa8    net.(*netFD).Read+0x58                        D:/Go/src/net/fd_windows.go:151
    8. #    0x544e53    net.(*conn).Read+0x73                        D:/Go/src/net/net.go:176
    9. #    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
    10. #    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
    11. #    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
    12. #    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
    13. #    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
    14. #    0x71470e    github.com/go-sql-driver/mysql.(*MySQLDriver).Open+0x4e        <autogenerated>:1
    15. #    0x4fd936    database/sql.(*DB).conn+0x136                    D:/Go/src/database/sql/sql.go:999
    16. #    0x4fc147    database/sql.(*DB).PingContext+0x97                D:/Go/src/database/sql/sql.go:631
    17. #    0x4fc349    database/sql.(*DB).Ping+0x49                    D:/Go/src/database/sql/sql.go:649
    18. #    0x782023    main.testCocurrencyMysqlOpt.func1+0x113                D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:951
    20. 1 @ 0x430461 0x429a21 0x428fae 0x4a8bd5 0x4a9e8a 0x4ab586 0x531fa9 0x544e54 0x67ff49 0x45d7e1
    21. #    0x428fad    internal/poll.runtime_pollWait+0x5d        D:/Go/src/runtime/netpoll.go:173
    22. #    0x4a8bd4    internal/poll.(*pollDesc).wait+0xb4        D:/Go/src/internal/poll/fd_poll_runtime.go:85
    23. #    0x4a9e89    internal/poll.(*ioSrv).ExecIO+0x139        D:/Go/src/internal/poll/fd_windows.go:205
    24. #    0x4ab585    internal/poll.(*FD).Read+0x265            D:/Go/src/internal/poll/fd_windows.go:458
    25. #    0x531fa8    net.(*netFD).Read+0x58                D:/Go/src/net/fd_windows.go:151
    26. #    0x544e53    net.(*conn).Read+0x73                D:/Go/src/net/net.go:176
    27. #    0x67ff48    net/http.(*connReader).backgroundRead+0x68    D:/Go/src/net/http/server.go:660
    29. 1 @ 0x430461 0x429a21 0x428fae 0x4a8bd5 0x4a9e8a 0x4ad3be 0x4ad6b1 0x5325e8 0x54ccd5 0x54afd0 0x68adb6 0x6899e9 0x689720 0x68a8f6 0x7821f3 0x45d7e1
    30. #    0x428fad    internal/poll.runtime_pollWait+0x5d        D:/Go/src/runtime/netpoll.go:173
    31. #    0x4a8bd4    internal/poll.(*pollDesc).wait+0xb4        D:/Go/src/internal/poll/fd_poll_runtime.go:85
    32. #    0x4a9e89    internal/poll.(*ioSrv).ExecIO+0x139        D:/Go/src/internal/poll/fd_windows.go:205
    33. #    0x4ad3bd    internal/poll.(*FD).acceptOne+0xad        D:/Go/src/internal/poll/fd_windows.go:767
    34. #    0x4ad6b0    internal/poll.(*FD).Accept+0x170        D:/Go/src/internal/poll/fd_windows.go:801
    35. #    0x5325e7    net.(*netFD).accept+0x87            D:/Go/src/net/fd_windows.go:192
    36. #    0x54ccd4    net.(*TCPListener).accept+0x34            D:/Go/src/net/tcpsock_posix.go:136
    37. #    0x54afcf    net.(*TCPListener).AcceptTCP+0x4f        D:/Go/src/net/tcpsock.go:234
    38. #    0x68adb5    net/http.tcpKeepAliveListener.Accept+0x35    D:/Go/src/net/http/server.go:3120
    39. #    0x6899e8    net/http.(*Server).Serve+0x1b8            D:/Go/src/net/http/server.go:2695
    40. #    0x68971f    net/http.(*Server).ListenAndServe+0xaf        D:/Go/src/net/http/server.go:2636
    41. #    0x68a8f5    net/http.ListenAndServe+0x85            D:/Go/src/net/http/server.go:2882
    42. #    0x7821f2    main.testCocurrencyMysqlOpt.func2+0x52        D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:960
    44. 1 @ 0x430461 0x430555 0x4048e2 0x4045bb 0x4fd2ba 0x45d7e1
    45. #    0x4fd2b9    database/sql.(*DB).connectionOpener+0x59    D:/Go/src/database/sql/sql.go:871
    47. 1 @ 0x430461 0x430555 0x441992 0x441560 0x4746d9 0x781ea4 0x781ef7 0x42ffc2 0x45d7e1
    48. #    0x44155f    sync.runtime_Semacquire+0x3f        D:/Go/src/runtime/sema.go:56
    49. #    0x4746d8    sync.(*WaitGroup).Wait+0x78        D:/Go/src/sync/waitgroup.go:131
    50. #    0x781ea3    main.testCocurrencyMysqlOpt+0x1f3    D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:973
    51. #    0x781ef6    main.main+0x26                D:/WorkSpace/Git/sql_proxy_git/confserver/src/app/test/main.go:977
    52. #    0x42ffc1    runtime.main+0x221            D:/Go/src/runtime/proc.go:195
    54. 1 @ 0x778a19 0x778807 0x775322 0x78170f 0x781a12 0x6869bb 0x6880d7 0x68963b 0x685854 0x45d7e1
    55. #    0x778a18    runtime/pprof.writeRuntimeProfile+0xa8    D:/Go/src/runtime/pprof/pprof.go:637
    56. #    0x778806    runtime/pprof.writeGoroutine+0xa6    D:/Go/src/runtime/pprof/pprof.go:599
    57. #    0x775321    runtime/pprof.(*Profile).WriteTo+0x3b1    D:/Go/src/runtime/pprof/pprof.go:310
    58. #    0x78170e    net/http/pprof.handler.ServeHTTP+0x1be    D:/Go/src/net/http/pprof/pprof.go:237
    59. #    0x781a11    net/http/pprof.Index+0x1e1        D:/Go/src/net/http/pprof/pprof.go:248
    60. #    0x6869ba    net/http.HandlerFunc.ServeHTTP+0x4a    D:/Go/src/net/http/server.go:1918
    61. #    0x6880d6    net/http.(*ServeMux).ServeHTTP+0x136    D:/Go/src/net/http/server.go:2254
    62. #    0x68963a    net/http.serverHandler.ServeHTTP+0xba    D:/Go/src/net/http/server.go:2619
    63. #    0x685853    net/http.(*conn).serve+0x723        D:/Go/src/net/http/server.go:1801

    我们发现大量的协程堵塞在了runtime_pollWait中，这样我们就明白了，我们的连接池没有限制最大连接数，导致连接数过多，有些连接会被MySQL拒绝掉，那么我们这里直接有响应，但是有一部分一直堵塞在了读取初始包这儿，导致了程序整体的堵塞。

    有了这个，那么分析这个问题就很清晰了。某个时间段，大量的读请求进来，导致连接池大量的创建新的连接，有一部分的连接没有创建成功，进入堵塞状态，但是读请求会先持有读写锁，于是无数的读请求挂起。这时候凑巧有几个写请求过来，这时候写锁发现有多个读锁持有了读写锁，那么会挂起等待。后续还会有读请求过来，但是由于已经有写锁在等待了，写锁无法获得锁，于是也挂起等待。于是就变成了多个持有写锁的协程堵塞在读取MySQL的回包中，1个写请求获得了写锁，多个写请求等待写锁，多个写请求堆积等待写锁获得读写锁。

    当堵塞的读请求全部超时后，那么最后一个读请求会唤醒被挂起的写请求，写请求执行完操作后，释放读写锁，这时候，几个写请求，N多堆积的读请求又会来争用读写锁，这又回到了一开始的场景，于是一直循环，直到读请求不堆积了，或者没有写请求了，这才会恢复。

    造成这种异常的原因，一个是没有个连接池设定最大连接数，还有一个是测试环境的MySQL的参数太低。但是程序这儿总得解决，最简单的方法就是给连接池设定最大连接数。把上面注释掉的代码加进去，整个程序就恢复正常了。这个也算自己的一个疏漏吧。

    共 0 条回复
    暂时没有人回复哦，赶紧抢沙发
    发表新回复
    验证码

    作者

    sryan
    today is a good day