1、事件還原
昨天下午，收到一個504的告警，顯然這是一個超時告警。當時由於手頭有其他事情，沒在意，就只是瞄了一眼，但是引起告警的方法很熟悉，是我寫的，第一反應有點詫異。
詫異之后，繼續處理手頭的工作。
一小時過后，又收到同樣的告警，顯然不是偶爾，肯定是哪兒出問題了，於是開始排查。
報警的接口是一個Controller層ControllerA的getControllerAMethod接口，其調用了多個微服務，並最終拼裝結果數據進行返回。出問題的是ServiceM，ServiceM服務里的getServiceMMethod方法邏輯也很簡單，主要是兩次數據庫查詢，從MySQL數據庫取到數據並返回給調用方。
調用鏈如下圖所示
2、環境介紹
語言：Go
DB：MySQL
數據庫交互：database/sql（公司在此基礎上做了一些定制和封裝，本質還是database/sql）
下面開始介紹這個問題的具體排查過程。
3、本能反應：從sql語句入手
拿到告警，從告警信息和對應的日志詳情信息來看，屬於超時問題。
第一反應是查看sql語句是否是慢查詢（雖然打心里知道這個可能性極低），sql語句很簡單，形如
select a, b, c from tableA where a in (a1,a2,a3)
不看執行計划也知道是可以命中索引的。
但還是看了下執行計划和真實的執行情況，分析結果和響應時間都相當可觀，沒有任何問題。
本能反應的排查就是這么索然無味，開始下一步排查。
4、上游排查：是否context時間耗盡
既然是超時問題，有可能是上游超時，也可能是下游超時，第一步排查已經排除了下游因為慢查詢導致超時的可能性。
那會不會是上游超時呢？顯然是有可能的，畢竟我們知道Go的context可以一路傳遞下去，所有服務調用都共用設置的總的時間額度。
而且從上圖可以發現ServiceM也是在上游接口的最后一步，所以如果上面的服務占用耗時過多，就會導致ServiceM的時間額度被壓縮的所剩無幾。
但是從日志排查可以發現，在ServiceM層看getServiceMethod方法對應sql查詢幾乎都是幾十毫秒返回。
從這個情況來看，不像是因為上游時間不夠導致的超時。
5、下游初步排查：rows成主要懷疑對象
既然上游時間額度充足，那問題還是大概率出在下游服務接口上。
於是開始仔細閱讀getServiceMMethod方法代碼，下面是代碼功能的偽代碼實現
rows, err = db.query(sql1)
if err != nil {
...
}
defer rows.Close()
for rows.Next() {
rows.scan(...)
}
rows, err = db.query(sql2)
if err != nil {
...
}
defer rows.Close()
for rows.Next() {
rows.scan(...)
}
看完代碼，開始有點小興奮，我想沒錯了，大概就是這個rows的問題了。
在《Go組件學習——database/sql數據庫連接池你用對了嗎》這篇我主要介紹了有關rows沒有正常關閉帶來的坑。所以開始聯想是否是因為在遍歷rows過程中沒有正確關閉數據庫連接，造成連接泄露，以至於后面的查詢拿不到連接導致超時。
原因我已經分析的清清楚楚，但是具體是哪一步除了問題呢，唯一能想到的是這里兩次查詢使用的是同一個rows對象，是不是某種情況導致在前一次已經關閉了連接而下一次查詢直接使用了關閉的連接而導致超時呢？
此時報警開始越來越頻繁，於是將這里兩次查詢由原來的一個rows接收改為使用兩個rows分別接收並關閉，然后提交代碼，測試通過后開始上線。
6、短暫的風平浪靜
代碼上線后，效果立竿見影。
告警立馬停止，日志也沒有再出現超時的信息了，一切又恢復到了往日的平靜，這讓我堅信，我應該是找到原因並解決問題了吧。
回到家后，心里還是有些不踏實，從11點開始，我拿出電腦，開始各種模擬、驗證和還原告警的原因。
7、三小時后，意識到風平浪靜可能是假象
從11點開始，一直到兩點，整整三個小時，我不但沒有找到原因，反而發現我的解決方式可能並沒有解決問題。
因為出問題的代碼並不復雜，如上所示，即只有兩個Select查詢。
於是我寫了一段一樣的代碼在本地測試，跑完后並沒有出現超時或者拿不到連接的情況。甚至，我將maxConn和IdleConn都設置為1也無不會出現超時。
除非，像文章《Go組件學習——database/sql數據庫連接池你用對了嗎》里說的一樣，在row.Next()過程中提前退出且沒有rows.Close()語句，才會造成下一次查詢拿不到連接的情況，即如下代碼所示
func oneConnWithRowsNextWithError() {
db, _ := db.Open("mysql", "root:rootroot@/dqm?charset=utf8&parseTime=True&loc=Local")
db.SetMaxOpenConns(1)
rows, err := db.Query("select * from test where name = 'jackie' limit 10")
if err != nil {
fmt.Println("query error")
}
i := 1
for rows.Next() {
i++
if i == 3 {
break
}
fmt.Println("close")
}
row, _ := db.Query("select * from test")
fmt.Println(row, rows)
}
但是原來的代碼是有defer rows.Close()方法的，這個連接最終肯定是會關閉的，不會出現內存泄露的情況。
這一刻，我想到了墨菲定律（因為沒有真正解決問題，問題還回再次出現）。
於是，我又開始扒源碼，結合日志，發現一條重要線索，就是很多查詢任務都是被主動cancel的。沒錯，這個cancel就是context.Timeout返回的cancel（這段代碼是我司在database/sql基礎上豐富的功能）。
cancel觸發的條件是執行database/sql中的QueryContext方法返回了err
// QueryContext executes a query that returns rows, typically a SELECT.
// The args are for any placeholder parameters in the query.
func (db *DB) QueryContext(ctx context.Context, query string, args ...interface{}) (*Rows, error) {
var rows *Rows
var err error
for i := 0; i < maxBadConnRetries; i++ {
rows, err = db.query(ctx, query, args, cachedOrNewConn)
if err != driver.ErrBadConn {
break
}
}
if err == driver.ErrBadConn {
return db.query(ctx, query, args, alwaysNewConn)
}
return rows, err
}
第一反應還是上游時間不夠，直接cancel context導致的，但是這個原因我們在前面已經排除了。
於是把這段代碼一直往下翻了好幾層，還一度懷疑到我們自研代碼中的一個參數叫QueryTimeout是否配置過小，但是去看了一眼配置（這一眼很重要，后面會說），發現是800ms，顯然是足夠的。
帶着越來越多的問題，我心不甘情不願的去睡覺了。
8、墨菲定律還是顯靈了
今天下午一點，我又收到了這個熟悉的告警，該來的總會來的（但是只收到一次告警）。
前面說了，這個cancel可能是一個重要信息，所以問題的原因是沒跑了，肯定是因為超時，超時可能是因為拿不到連接。
因為getServiceMMethod已經排查一通了，並沒有連接泄露的情況，但是其他地方會不會有泄漏呢？於是排查了ServiceM服務的所有代碼，對於使用到rows對象的代碼檢查是否有正常關閉。
排查后，希望破滅。
到此為止，我打心里已經排除了是連接泄露的問題了。
期間，我還問了我們DBA，因為我翻了下日志，今天上午8點左右有幾條查詢都在幾百毫秒，懷疑是DB狀態異常導致的。DBA給我的回復是數據庫非常正常。
我自己也看了監控，DB的狀態和往日相比沒有什么流量異常，也沒有連接池數量的大起大落。
同事說了前幾天上了新功能，量比以前大，於是我也看了下新功能對應的代碼，也沒發現問題。
9、准備"曲線救國"
我想要的根本原因還沒有找到，於是開始想是否可以通過其他方式來規避這個未知的問題呢。畢竟解決問題的最好方式就是不解決（換另一種方式）。
准備將ServiceM方法的超時時間調大。
也准備在ServiceM服務的getServiceMMethod方法添加緩存，通過緩存來抵擋一部分請求量。
行吧，就到此為止，明天先用這兩招試試看。
於是，我准備站起來活動活動，順便在腦海里盤點下這個告警的來龍去脈。
10、靈機一動，我找到了真相
上游告警，下游超時 ->
排除上游時間不夠 ->
排除下游rows未關閉 ->
排除數據庫狀態不穩定 ->
確定是下游超時 ->
懷疑是拿不到連接 ->
拿不到連接，拿不到連接， 拿不到連接
於是又去翻數據庫參數配置，剛上面是為了翻QueryTimeout參數，依稀記得這里的連接池設置不大。翻到配置看了下，idleConn=X，maxConn=Y。
再去看了一眼getServiceMMethod方法的QPS監控，我覺得我找到了真相。
從凌晨到早上八點，QPS一直在上升，一直到8點左右，突破Y，而maxConn=Y。
所以應該是超過maxConn，導致后面的查詢任務拿不到連接只能等待，等待到超時時間后還是沒有拿到連接，所以觸發上面說的cancel，從而也導致在上游看到的超時告警都是ServiceM的getServiceMMethod執行了超時時間，因為一直在等待。
那么為什么圖中有超過Y的時候沒有一直報警呢，我理解應該是這期間有其他任務已經執行完查詢任務將連接放回連接池，后面來的請求就可以直接使用了，畢竟還會有一個超時時間的等待窗口。
那么為什么之前沒有出現這種報警呢，我理解是之前量比較小，最近同事上線了新功能，導致該接口被調用次數增加，才凸顯了這個問題。
11、 總結
其實，最后原因可能很簡單，就是量起來了，配置的連接數顯得小了，導致后來的查詢任務拿不到連接超時了。
但是這個超時橫跨Controller層到Service以及最底層的DB層，而每一層都可能會導致超時，所以排查相對比較困難。
下面是一些馬后炮要點
- 最近改動的代碼需要格外重視。如果以前長時間沒有告警，最近上完新代碼告警了，大概率和上線有關系（本次超時其實和新上線代碼也有關系，雖然代碼本身沒有問題，但是新上線后流量變大了）
- 善用工具。用好監控和日志等系統工具，從中找出有用的線索和聯系。
- 自上而下排查並追蹤。針對不好定位的bug，可以按照一定順序比如調用順序依次檢查、驗證、排除，直到找到原因。