一行代碼引發的協程泄露

時間 2020-06-01

標籤一行代碼引發泄露简体版

原文原文鏈接

前言

最終定位到的結果比較蠢，巨佬能夠直接查看結果，本文只爲記錄尋找該bug時使用的方法而生。
本人平日維護一個公司運營平臺的一個配置庫，因爲降級措施比較好，並且公司容器實例也比較多，因此在爆發錯誤的時候並未及時跟進。該問題應該從該服務出生開始就已經有了，一直沒有爆發的緣由應該是由於之前迭代得比較多，一週也差很少會發布四到五次，再加上平臺在去年使用人數仍是比較少的，後面逐漸成爲公司一箇中流砥柱的產品，被許多部門所使用，因此問題就爆發了。redis

第一次猜測

「這服務怎麼協程忽然暴漲了」
第一次協程暴漲的時候，發現有一臺實例忽然就跪了，協程數瘋狂暴漲，內存也瘋狂暴漲，第一反應是db出現了慢查詢，可是實際上。而查看監控，並無特別多接口跪，如圖。緩存

而實際上能很明顯看到有幾個實例的協程數直線上漲。併發

其實由於服務設計緣由，沒有那麼多接口跪是符合預期的，由於其餘接口都作了內存全表緩存，至於爲何作內存全表緩存就後面再說吧。經過pprof定位，很容易就發現那幾個跪了的接口都有一個共同點，協程泄露。
此時掃了一眼代碼，那幾個接口除了沒有作緩存，其餘實現都蠻合理的，由於懷疑是慢查詢了，因此嘗試去掃了一下表，大概最長耗時接近1s，該表數據也差很少到了3w多數據了，因此認爲是由於掃這個表致使線程被佔用，而當多臺機子都併發讀該接口時由於慢查詢給堵住，沒有超時設置因此獲取協程的吞吐量不成比了。
因此就溜下去給這個接口作了內存緩存，暫時緩解了兩三個星期，可是幾周事後又出現了協程泄露，不得而解。。

第二次猜測

再次出現協程泄露時，沒什麼其餘手段去排查了，只能幹讀代碼，不是由於讀庫的緣由，那是由於什麼呢？
產生了這個想法的我，看向了寫操做的代碼，有沒有多是由於讀寫沒分離，寫超時了致使出現這個問題呢。
由於再次出現協程泄露的時間很奇特，在半夜四點，忽然給電話打醒。因此突發奇想，跟同事去查了一下當天凌晨4點平臺的操做，發現確實，有一我的在晚上4點的時候申請了一個東西，寫了庫，時間剛好吻合。
因此確實是由於寫數據的問題了，因而我又去掃了一眼代碼，發現整個庫表都是讀主庫的，從庫歷來不用，emmmmmm。因而就給服務作了一次讀寫分離，作起來也不復雜。
不出所望過了兩週，問題又爆發了。。框架

第三次猜測

首先，我在質疑代碼裏的timeout真的是奏效的嗎，爲何明明設置了超時時間還會超時，並且不單隻只有代碼經過框架設置了超時，db平臺也設置了超時，按道理來講應該會kill掉的。不會是某個時刻操做比較多庫比較渣因此就跪了，可是實際上操做的qps並不高，秉着質疑，我發現，線程池裏只設置了10個線程數，對於這個服務來講10個線程徹底不夠啊，因此我就跑去擴線程了。
不出所望依然是過了一兩週，問題又來了。。ui

暫時是最後一次猜測

此次是大半夜忽然連續出了兩三次，並且出的頻率還特別高，遷移了實例後過一兩個鍾又會有實例協程泄露。因此剛好發現，全部會形成忽然協程泄露的操做，都是調用了一個寫數據的接口致使的。把接口來回看了好幾回，硬是沒看出問題。可是我意識到一件事，這個接口調用了三次db，而我設置db查詢/寫的超時時間是3s，而上游卻過了10s才熔斷，那麼按道理來講應該是9s後會超時，感受到了事情有一點不對。
因此再一次協程泄露時，我暫時沒有遷移實例，而是爬上了實例查看實例日誌，發現某一行debug日誌並未執行。看來問題已經縮小到某幾行代碼了。
沒錯，我在開始懷疑gorm框架有問題了，看起了源碼。發現咱們實現查找最大值的代碼很神奇，居然是拿了rows。代碼以下。spa

func GetMax(ctx context.Context) (int64, error) {
        var max int64 = 0
        db, err := GetConnection(ctx, DatabaseName)
        if err != nil {
                return max, err
        }
        rows, err := db.Table(TableName).Select("max(xxx) as max").Rows()
        if err != nil {
                return max, err
        }
        if rows.Next() {
                err := rows.Scan(&max)
                if err != nil {
                        return max, err
                }
        }
        return max, nil
}
複製代碼

乍一眼看，貌似沒啥問題，看一下next的源碼，在沒有下一行數據時，不會將rows close掉，代碼以下，代碼來自go 1.13.4源碼，只有中文註釋是本身加上的：線程

func (rs *Rows) Next() bool {
        var doClose, ok bool
        withLock(rs.closemu.RLocker(), func() {
                doClose, ok = rs.nextLocked()
        })
        if doClose {   // 這裏當須要close的時候會將線程釋放掉
                rs.Close()
        }
        return ok // 而返回的true/false是決定能不能拿到數據的
}

func (rs *Rows) nextLocked() (doClose, ok bool) {
        if rs.closed {
                return false, false
        }

        // Lock the driver connection before calling the driver interface
        // rowsi to prevent a Tx from rolling back the connection at the same time.
        rs.dc.Lock()
        defer rs.dc.Unlock()

        if rs.lastcols == nil {
                rs.lastcols = make([]driver.Value, len(rs.rowsi.Columns()))
        }

        rs.lasterr = rs.rowsi.Next(rs.lastcols)
        if rs.lasterr != nil {
                // Close the connection if there is a driver error.
                if rs.lasterr != io.EOF {
                        return true, false
                }
                nextResultSet, ok := rs.rowsi.(driver.RowsNextResultSet)
                if !ok {
                        return true, false
                }
                // The driver is at the end of the current result set.
                // Test to see if there is another result set after the current one.
                // Only close Rows if there is no further result sets to read.
                if !nextResultSet.HasNextResultSet() { // 當沒有下一行數據時，next是false，close是true
                        doClose = true
                }
                return doClose, false
        }
        return false, true
}
複製代碼

咦這個不close真的不會有問題嗎？咱們再看看這個rows是從哪裏拿出來的，沒錯線程池，那麼不close掉是否是會致使這個線程不會放回去線程池裏呢？咱們看看close的代碼，代碼以下：debug

func (rs *Rows) close(err error) error {
        rs.closemu.Lock()
        defer rs.closemu.Unlock()

        if rs.closed {
                return nil
        }
        rs.closed = true

        if rs.lasterr == nil {
                rs.lasterr = err
        }

        withLock(rs.dc, func() {
                err = rs.rowsi.Close()
        })
        if fn := rowsCloseHook(); fn != nil {
                fn(rs, &err)
        }
        if rs.cancel != nil {
                rs.cancel()
        }

        if rs.closeStmt != nil {
                rs.closeStmt.Close()
        }
        rs.releaseConn(err)   // 這裏會釋放鏈接
        return err
}
複製代碼

事實上，應該是的。因此事情到這裏應該是已經解決了。解決完的代碼以下：設計

func GetMax(ctx context.Context) (int64, error) {
        var max int64 = 0
        db, err := GetConnection(ctx, DatabaseName)
        if err != nil {
                return max, err
        }
        rows, err := db.Table(TableName).Select("max(xxx) as max").Rows()
        if err != nil {
                return max, err
        }
        defer rows.Close()     // 只由於少了這一行
        if rows.Next() {
                err := rows.Scan(&max)
                if err != nil {
                        return max, err
                }
        }
        return max, nil
}
複製代碼

可是實際上取max值只會有一個值，爲什麼會使用rows而不使用row呢？不得而知。由於根據go源碼來看若是這麼寫的話是不須要本身去close掉線程的。日誌

for rows.Next() {  // 這裏改爲循環一直走下一個
        err := rows.Scan(&max)
        if err != nil {
                return max, err
        }
}
複製代碼

還有另外一個問題是，爲何會兩週一次呢，算一算，實例差很少有15臺，而進行這個查max的操做只有在申請某個配置的時候纔會觸發，而線程池裏有10個線程，因此在假設請求是均衡的狀況下，要申請100+次纔會開始命中這個問題。並且也只有db線程數不夠的機器纔會出現這種問題，再加上這個服務已經相對比較穩定了，好久沒有怎麼加過需求了，因此容器不會重啓，內存不會重置。至於GC到底能不能把解決這個問題呢，應該是不行的，由於解決了只會讓你的線程數減小。
哎，真的是菜，定位問題都那麼難。主要仍是沒啥經驗吧，全部接口都報錯了，一開始無從下手，直到某天凌晨給報警電話打醒，才突發奇想去定位這個問題。