HTTP TimeoutHandler 所踩到的雷與解決方式，需要額外判斷 Request.Context() 的狀態

最近遇到在 HTTP 伺服器壓力測試時遇到棘手的問題，從 nginx logs 發現伺服器回應許多 HTTP 503 service unavailable 的錯誤，一路追蹤最終發現是程式碼實作錯誤，記錄其筆記提醒自己不要忘記這個雷。

測試架構，clients 建立 n 個連線到 web server (送出 n 個要求)，而 web server 建立 m 個連線到 database server，n 遠遠大於 m

想從資料庫撈出什麼線索

從 logs 中發現大多要求 (requests) 都需要資料庫交易 (transactions) 處理，懷疑是資料庫出了什麼問題，輸入 SQL 印出內部引擎狀態：

SHOW ENGINE INNODB STATUS

從引擎狀態中，沒有發現任何的 transaction dead locks，而是發現數多個 transactions 持續運作很長一段時間沒有釋放，佔據伺服器與資料庫的最大允許連線數：

------------ TRANSACTIONS ------------
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 1321060, ACTIVE 1193 sec 2 lock struct(s), heap size 360, 1 row lock(s) MySQL thread id 6822, OS thread handle 0x2b62f774b700, query id 3019563 [my-ip] root cleaning up

雖然嘗試按照這篇文章 的方法，開啟資料庫的歷史紀錄查詢紀錄，但實務上沒有撈到任何有用的資訊，只知道連線開啟後，執行 BEGIN 就沒有了……。

重新審視 HTTP handler

只能重新審視處理要求的函式 (handler)，從程式碼撈出一段範例：

import (
   "database/sql"
   "net/http"
)

func exampleHandler(db *sql.DB) http.Handler {
   return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
      // prepare...

      tx, err := db.Begin()
      if err != nil {
         panic(err)
      }
      defer tx.Rollback()

      // do transaction......

      if err := tx.Commit(); err != nil {
         panic(err)
      }

      // response...... 
   })
}

初看處理都有加入 Rollback() 抑或是 Commit()，理論上應該是不會有任何問題才是……。

回到最上層的 HTTP server 架構處理，才想起有使用到 http.TimeoutHandler，用來避免處理要求要太久時間：

package main

import (
   "net/http"
   "time"
   "github.com/gorilla/mux"
)

func recoveryHandler(next http.Handler) http.Handler {
   return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
      defer func() {
         if r := recover(); r != nil {
            // TODO: Log panic
            w.WriteHeader(http.StatusInternalServerError)
         }
      }()
      next.ServeHTTP(w, req)
   })
}

func main() {
   r := mux.NewRouter()
   r.Handle("/", exampleHandler(db))

   h := http.TimeoutHandler(r, time.Second*1000, "timeout")
   http.ListenAndServe(":8080", recoveryHandler(h))
}

仔細研究 http.TimeoutHandler 內部的實作，發現是開啟另一個 goroutine 來執行其 handler，並利用 go 1.7 引進的 context.Context 來通知是否已經連線逾時 (timeout)，讓 handler 利用 req.Context() 來中斷要求處理。以下為 http.TimeoutHandler的部分實作：

func (h *timeoutHandler) ServeHTTP(w ResponseWriter, r *Request) {
   ctx, cancelCtx := context.WithTimeout(r.Context(), h.dt)
   defer cancelCtx()
   r = r.WithContext(ctx)
   
   done := make(chan struct{})
   tw := &timeoutWriter{
      w: w,
      h: make(Header),
   }
   panicChan := make(chan interface{}, 1)
   go func() {
      defer func() {
         if p := recover(); p != nil {
            panicChan <- p
         }
      }()
      h.handler.ServeHTTP(tw, r)
      close(done)
   }()
   
   select {
   case p := <-panicChan:
      // handler panic 錯誤，繼續往上層丟
      panic(p)
   case <-done:
      // 在限制時間內完成，回應 handler 寫入資料
      tw.mu.Lock()
      defer tw.mu.Unlock()
      dst := w.Header()
      for k, vv := range tw.h {
         dst[k] = vv
      }
      if !tw.wroteHeader {
         tw.code = StatusOK
      }
      w.WriteHeader(tw.code)
      w.Write(tw.wbuf.Bytes())
   case <-ctx.Done():
      // 限制時間已到，回應 HTTP 503 (ServiceUnavailable)
      tw.mu.Lock()
      defer tw.mu.Unlock()
      w.WriteHeader(StatusServiceUnavailable)
      io.WriteString(w, h.errorBody())
      tw.timedOut = true
   }
}

而目前的程式碼沒有處理 context 的取消通知，在大量連線情況下，會導致大量的 goroutines 常駐在系統，大部分都在等待建立 transaction，而那些已建立 transaction 的 goroutines，卻因為其他大量等待的 goroutines 所導致的 starvation，持續占用 transaction 資源而不能釋放，進而導致從資料庫狀態觀察到的問題：transactions active for a long time。(對於 Go scheduling 不熟悉，根據過往的經驗知識猜測是 starvation，從 logs 中有觀察到 goroutines 同時運行數量超過 30 萬個，甚至導致 out-of-memory)

大量 goroutines 示意，藍色表示有建立 transaction 的 goroutines，而白色表示等待建立 transaction 的 goroutines，猜測 go scheduler 因大量的 goroutines 需要執行，始終沒有將運算資源分到藍色 goroutines，造成 starvation (在我們的測試中，總 goroutines 超過 30 萬個)

附註：starvation 是程序始終拿不到系統資源 (CPU) 執行其工作，更詳細請參考 Wiki: Starvation。另外資料庫連線數可以透過 DB.SetMaxOpenConns 限制

解決方法

為了避免大量連線所造成的 starvation 發生，handler 應該調整成當 http.TimeoutHandler 逾時 (timeout) 時，就要停止繼續執行，釋放該 handler 所佔住的 goroutine 資源 (連線逾時都已經回應 HTTP 503，期望是直接結束當前工作，且所有已完成結果應該要 rollback)。

修改 exampleHandler 程式碼，改用支援能傳入 context 的版本，BeginTx，並加入新的錯誤處理：

func exampleHandler(db *sql.DB) http.Handler {
   return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
      // prepare...

      ctx := req.Context()
      defer func() {
         if r := recover(); r != nil && r != ctx.Err() {
            panic(r)
         }
      }()
      
      tx, err := db.BeginTx(ctx, nil)
      if err != nil {
         panic(err)
      }
      defer tx.Rollback()

      // do transaction......

      if err := tx.Commit(); err != nil {
         panic(err)
      }

      // response......
   })
}

由於 Line 12 以及 Line 20 所使用 sql package，若發現所傳入的 ctx 已經結束，會直接回傳的 ctx.Err()，若 recover 所拿到的 panic 資料是 ctx.Err()，那表示是中斷 request 處理，不將其錯誤往上層傳。

修改後的程式碼，在經過實務測試後，不會再出現之前所遇到 transactions 占用的問題。

當然其他更複雜的 handlers 也陸續修改實作，在與其他微服務溝通前，先判斷 req.Context() 是否已經結束 (be canceled)，才決定是否繼續執行其處理，這似乎又能讓 HTTP 伺服器更穩定一些。