一次線上接口超時的排查過程

一、事件還原

昨天下午，收到一個504的告警，顯然這是一個超時告警。當時因爲手頭有其餘事情，沒在乎，就只是瞄了一眼，可是引發告警的方法很熟悉，是我寫的，第一反應有點詫異。

詫異以後，繼續處理手頭的工做。

一小時事後，又收到一樣的告警，顯然不是偶爾，確定是哪兒出問題了，因而開始排查。

報警的接口是一個Controller層ControllerA的getControllerAMethod接口，其調用了多個微服務，並最終拼裝結果數據進行返回。出問題的是ServiceM，ServiceM服務裏的getServiceMMethod方法邏輯也很簡單，主要是兩次數據庫查詢，從MySQL數據庫取到數據並返回給調用方。

調用鏈以下圖所示

二、環境介紹

**語言：**Go

**DB：**MySQL

**數據庫交互：**database/sql（公司在此基礎上作了一些定製和封裝，本質仍是database/sql）

下面開始介紹這個問題的具體排查過程。

三、本能反應：從sql語句入手

拿到告警，從告警信息和對應的日誌詳情信息來看，屬於超時問題。

第一反應是查看sql語句是不是慢查詢（雖然打內心知道這個可能性極低），sql語句很簡單，形如

select a, b, c from tableA where a in (a1,a2,a3)
複製代碼

不看執行計劃也知道是能夠命中索引的。

但仍是看了下執行計劃和真實的執行狀況，分析結果和響應時間都至關可觀，沒有任何問題。

本能反應的排查就是這麼索然無味，開始下一步排查。

四、上游排查：是否context時間耗盡

既然是超時問題，有多是上游超時，也多是下游超時，第一步排查已經排除了下游由於慢查詢致使超時的可能性。

那會不會是上游超時呢？顯然是有可能的，畢竟咱們知道Go的context能夠一路傳遞下去，全部服務調用都共用設置的總的時間額度。

並且從上圖能夠發現ServiceM也是在上游接口的最後一步，因此若是上面的服務佔用耗時過多，就會致使ServiceM的時間額度被壓縮的所剩無幾。

可是從日誌排查能夠發現，在ServiceM層看getServiceMethod方法對應sql查詢幾乎都是幾十毫秒返回。

從這個狀況來看，不像是由於上游時間不夠致使的超時。

五、下游初步排查：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分別接收並關閉，而後提交代碼，測試經過後開始上線。

六、短暫的風平浪靜

代碼上線後，效果立竿見影。

告警立馬中止，日誌也沒有再出現超時的信息了，一切又恢復到了往日的平靜，這讓我堅信，我應該是找到緣由並解決問題了吧。

回到家後，內心仍是有些不踏實，從11點開始，我拿出電腦，開始各類模擬、驗證和還原告警的緣由。

七、三小時後，意識到風平浪靜多是假象

從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，顯然是足夠的。

帶着愈來愈多的問題，我心不甘情不肯的去睡覺了。

八、墨菲定律仍是顯靈了

今天下午一點，我又收到了這個熟悉的告警，該來的總會來的（可是隻收到一次告警）。

前面說了，這個cancel多是一個重要信息，因此問題的緣由是沒跑了，確定是由於超時，超時多是由於拿不到鏈接。

由於getServiceMMethod已經排查一通了，並無鏈接泄露的狀況，可是其餘地方會不會有泄漏呢？因而排查了ServiceM服務的全部代碼，對於使用到rows對象的代碼檢查是否有正常關閉。

排查後，但願破滅。

到此爲止，我打內心已經排除了是鏈接泄露的問題了。

期間，我還問了咱們DBA，由於我翻了下日誌，今天上午8點左右有幾條查詢都在幾百毫秒，懷疑是DB狀態異常致使的。DBA給個人回覆是數據庫很是正常。

我本身也看了監控，DB的狀態和往日相比沒有什麼流量異常，也沒有鏈接池數量的大起大落。

同事說了前幾天上了新功能，量比之前大，因而我也看了下新功能對應的代碼，也沒發現問題。

九、準備"曲線救國"

我想要的根本緣由尚未找到，因而開始想是否能夠經過其餘方式來規避這個未知的問題呢。畢竟解決問題的最好方式就是不解決（換另外一種方式）。

準備將ServiceM方法的超時時間調大。

也準備在ServiceM服務的getServiceMMethod方法添加緩存，經過緩存來抵擋一部分請求量。

行吧，就到此爲止，明天先用這兩招試試看。

因而，我準備站起來活動活動，順便在腦海裏盤點下這個告警的前因後果。

十、靈機一動，我找到了真相

上游告警，下游超時 ->

排除上游時間不夠 ->

排除下游rows未關閉 ->

排除數據庫狀態不穩定 ->

肯定是下游超時 ->

懷疑是拿不到鏈接 ->

拿不到鏈接，拿不到鏈接， 拿不到鏈接

因而又去翻數據庫參數配置，剛上面是爲了翻QueryTimeout參數，依稀記得這裏的鏈接池設置不大。翻到配置看了下，idleConn=X，maxConn=Y。

再去看了一眼getServiceMMethod方法的QPS監控，我以爲我找到了真相。

從凌晨到早上八點，QPS一直在上升，一直到8點左右，突破Y，而maxConn=Y。

因此應該是超過maxConn，致使後面的查詢任務拿不到鏈接只能等待，等待到超時時間後仍是沒有拿到鏈接，因此觸發上面說的cancel，從而也致使在上游看到的超時告警都是ServiceM的getServiceMMethod執行了超時時間，由於一直在等待。

那麼爲何圖中有超過Y的時候沒有一直報警呢，我理解應該是這期間有其餘任務已經執行完查詢任務將鏈接放回鏈接池，後面來的請求就能夠直接使用了，畢竟還會有一個超時時間的等待窗口。

那麼爲何以前沒有出現這種報警呢，我理解是以前量比較小，最近同事上線了新功能，致使該接口被調用次數增長，才凸顯了這個問題。

十一、總結

其實，最後緣由可能很簡單，就是量起來了，配置的鏈接數顯得小了，致使後來的查詢任務拿不到鏈接超時了。

可是這個超時橫跨Controller層到Service以及最底層的DB層，而每一層均可能會致使超時，因此排查相對比較困難。

下面是一些馬後炮要點

• 最近改動的代碼須要格外重視。若是之前長時間沒有告警，最近上完新代碼告警了，大機率和上線有關係（本次超時其實和新上線代碼也有關係，雖然代碼自己沒有問題，可是新上線後流量變大了）
• 善用工具。用好監控和日誌等系統工具，從中找出有用的線索和聯繫。
• 自上而下排查並追蹤。針對很差定位的bug，能夠按照必定順序好比調用順序依次檢查、驗證、排除，直到找到緣由。

我的公衆號JackieZheng，歡迎關注~