Golang 微服務優化實戰

linvon發表於2020-08-27

最近幾天給推薦業務做了一次流程優化，請求耗時的 P95 分位降低了一半，記錄了一下排查與優化的歷程，也方便有需要的朋友參考。文章寫在了自己的部落格上，詳見連結

最近幾天給推薦業務做了一次流程優化，請求耗時的 P95 分位降低了一半，記錄一下排查與優化的歷程，也方便有需要的朋友參考。

背景

熟悉推薦的同學應該知道，推薦中的歷史池、召回 Recall 和 Ranking 是比較重要的部分。同時各個模型有輕有重，資料量有大有小，並且模型之間可能還存在依賴關係。而我們的推薦同學重點負責演算法和模型的研發，在工程上我們便接手來做優化。

序列改並行

首先想到的優化思路便是串改並，我們的服務是使用 Go 來搭建的，併發跑模型是很容易的。但改併發並不能一蹴而就，我們提到過模型之前很多是存在依賴關係的，有些模型可能會需要上一個模型的結果作為引數。所以在處理模型的串改並上，我們做了下面的事情：

理清模型時序依賴，使用配置檔案控制哪些模型可以併發執行，哪些不能
在模型佇列週期和每個模型執行週期做好時間 Metrics，方便直觀的觀察執行效率
重構同時走讀流程程式碼，檢視其它可非同步執行的流程，拆離主流程

最終通過 Metrics 日誌統計，發現模型佇列平均可以優化近一半的耗時

使用 Jaeger 追蹤請求流程

Jaeger 是一個優秀的分散式微服務事務追蹤軟體。即使一個請求會經過不同的微服務來完成業務，它仍然可以追蹤一個完整的會話上下文。

點選一個請求會話，可以進入到它的詳情頁

可以看到在整個請求的分階段耗時都展現了出來，我們可以清楚的瞭解到整個請求過程中時間都花費在了什麼地方。

對於 Go 服務來講，應用 Jaeger 也非常簡單，可以參照 Github 上的開源例項來實現，也可以直接參閱官方的文件

以 opentracing 為例，在使用時可以設定 Operation 和 Tags，方便給這一個事務做歸類，同時在 Jaeger 中我們可以直接對想看的型別做篩選

span, _ := opentracing.StartSpanFromContext(ctx, "RecallStrategies", opentracing.Tag{Key: string(ext.SpanKind), Value: "Recall"})
defer span.Finish()

既然 Jaeger 已經可以將耗時展現的如此細緻了，為什麼還需要其他優化策略呢？很遺憾，Jaeger 並不是完全穩定可靠的，由於網路或其他一些原因，流程中的 Span 可能會丟掉，導致一整個會話並不能統計完全。因此我們需要一些其他穩定可靠的手段來完善耗時統計。

Prometheus & Grafana

如果做過服務監控的同學可能不會對這兩個元件陌生。

Prometheus 是一個開源的監控與報警系統，它本質上是一個時序資料庫，會從微服務上發現並拉取含有時間序列的資料指標並做分析統計儲存。上手可以參考官方文件，同時也可以參考 prometheus-book，都是不錯的教程
Grafana 是一個資料視覺化儀表盤工具，用以將你收集儲存的資料指標展示出來

通常情況下，Prometheus + Grafana 是很有效的搭配，在上面推薦的教程中也有提到這兩種元件的組合使用方式。實際上就是在 Grafana 中利用 promQL 向 Prometheus 查詢時序資料。這裡再推薦一篇新手教程，這兩個元件的搭建我們在本文中不再贅述

使用這種組合可以監控很多種我們需要的資料，比方說介面的 QPS，系統的 CPU、記憶體等效能指標，請求的耗時、延時等。在本次優化中，我們需要使用到的便是 Prometheus 的統計直方圖功能，將我們需要統計的函式耗時記錄到 Prometheus 中，利用其自身的直方圖功能構建出每個函式的耗時分佈直方圖。

對於 Prometheus 的使用我們不再贅述，有需要的同學可以直接參考官方的 API 文件，這裡以 Go 為例：

import (
    "github.com/prometheus/client_golang/prometheus"
)

var elapsedHis = prometheus.NewHistogramVec(prometheus.HistogramOpts{
    Namespace: "rec",
    Name:      "rec_func_elapsed",
    Help:      "Rec Function Elapsed Time",
    Buckets:   append(prometheus.LinearBuckets(0, 10, 10), prometheus.ExponentialBuckets(100, 2, 4)...),
}, []string{"func"})

func InitProm() {
    prometheus.MustRegister(elapsedHis)
    http.Handle("/metrics", promhttp.Handler())
    log.Println("start serving prometheus")
}

func AddFuncElapsed(funcName string, t time.Time) {
    elapsed := int64(time.Since(t)) / 1e6
    elapsedHis.WithLabelValues(funcName).Observe(float64(elapsed))
}

首先建立一個直方桶，桶的分槽範圍我們採用的是線性增長（LinearBuckets）加指數增長（ExponentialBuckets），最終桶分佈是 0 10 20 30 40 … 100 200 400 800 這樣。之後需要將建立好的桶註冊，並啟用 HTTP 服務，將 metrics 介面暴露給 Prometheus 用以抓取資料。

之後便可以在需要記錄的函式內新增函式回撥，用以統計該函式執行所耗費的時間

func A() {
    defer base.AddFuncElapsed("A", time.Now())  

  ...
}

完善好服務後，訪問服務的 ip:port/metrics 應該可以看到我們服務所暴露出來的指標內容。Prometheus 會抓取這些指標，這時候我們便可以在 Grafana 中繪製我們所需要的分佈圖。在這裡我們所需要的是根據直方桶來繪製函式延時 95 分位的圖，即 95% 的函式耗時均低於該所得值，用以觀察絕大部分函式的耗時，個例不再做考慮。

建圖後可以看到類似的效果

圖中我們可以看到所有函式的 95 分位的耗時時長，值得注意的是 callRecall 函式負責了對於 Recall 的呼叫，而在 Recall 中的耗時實際上比 callRecall 低了很多，甚至不到一半。然而走讀程式碼並沒有發現有其他的耗時操作，這就成為了一個比較困惑的點。為了排查除去 Recall 自身還有什麼其他的耗時操作，我們就需要另一個工具了

Go tool pprof

熟悉 Go 優化的同學應該對這個工具非常熟悉，這是 Go 自帶的效能分析工具，在 Go 程式或服務上引入"net/http/pprof"包，程式便會自動構建 Go 執行時分析資料。

通過這個工具我們可以排查 Go 程式執行時的 CPU 分佈、記憶體的分配情況等等，這裡我們需要的是程式的 CPU 佔用，來找找是否有某些計算密集操作拖慢了整個流程。

我們在程式中加入包引用，通過本地工具獲取執行時資料：

go tool pprof -http=:8080 http://ip:port/debug/pprof/profile 該工具會將執行時資料生成視覺化圖表 svg 檔案，使用瀏覽器開啟後找到 Flame 可以看到如下內容

可以看到在 callRecall 過程中對於 json 資料的 Unmarshal 佔用了很長時間的 CPU，可以推測因為 Recall 獲取到的資料量非常大，介面返回資料後對於資料的格式化佔用了非常大的時間。實際上 Go 標準庫的 JSON 庫效能並不是很優秀，有經驗的 Gopher 們往往會採用第三方 JSON 來加快序列化、反序列化過程。

而在本例中，對於結構龐大且複雜的 Struct 資料，使用 jsoniter 是一個非常好的選擇。json-iterator 使用 modern-go/reflect2 來優化反射效能，因此在 Struct 的 Unmarshal 上效能非常好，在引入 jsoniter 後，我們再次檢視 CPU 分佈如下