一次錯誤使用 go-cache 導致出現的線上問題

haohongfan發表於2021-04-27
Go

話說一個美滋滋的上午, 突然就出現大量報警, 介面大量請求都響應超時了.

排查過程

  1. 檢視伺服器的監控系統, CPU, 記憶體, 負載等指標正常
  2. 排查日誌, 日誌能夠響應的結果也正常. request.log 中響應時長高達數秒
  3. 檢視資料庫, codis 監控, 各項指標正常

不得已, 只能開啟線上 pprof 檢視 Go 相關引數是否正常. 果真一下子就找到問題發生的原因

go-cache

這是當時線上 pprof 的截圖, 發現 40 多萬 goroutine 都阻塞在 go-cache 的 Set 函式上. 更準確的說 40 多萬 goroutine 在發生很嚴重的鎖競爭. 這就讓人覺得很意外了.

幸好當時在壓測介面的時候, 為了避免 go-cache 的影響結果的影響, 引入了一個配置項來控制是否開啟 go-cache, 於是立馬線上關閉 go-cache, 介面響應恢復正常.

問題來了

雖說問題解決了, 但是是由於什麼原因造成的呢?

  1. 為什麼 go-cache 會發生這麼嚴重的鎖競爭 ?
  2. 是由於 go-cache 有程式碼 bug 嗎 ?
  3. 如何才能穩定復現呢 ?

go-cache 原始碼剖析

為了探究這個 bug 引起的原因, 我將整個 go-cache的原始碼讀了一遍, 其實 go-cache 相對於 freecache, bigcache 還是相對簡單許多.

type cache struct {
	defaultExpiration time.Duration
	items             map[string]Item
	mu                sync.RWMutex
	onEvicted         func(string, interface{})
	janitor           *janitor
}

從結構體上, go-cache 主要還是由 map + RWMutex 組成.

Set -- go-cache 最重要的函式

// Add an item to the cache, replacing any existing item. If the duration is 0
// (DefaultExpiration), the cache's default expiration time is used. If it is -1
// (NoExpiration), the item never expires.
func (c *cache) Set(k string, x interface{}, d time.Duration) {
	// "Inlining" of set
	var e int64
	if d == DefaultExpiration {
		d = c.defaultExpiration
	}
	if d > 0 {
		e = time.Now().Add(d).UnixNano()
	}
	c.mu.Lock()
	c.items[k] = Item{
		Object:     x,
		Expiration: e,
	}
	// TODO: Calls to mu.Unlock are currently not deferred because defer
	// adds ~200 ns (as of go1.)
	c.mu.Unlock()
}

Set 需要三個引數: key, value, d(過期時間). 如果 d 為 0, 則使用 go-cache 預設過期時間, 這個預設過期時間是go-cache.New()時設定的. 如果 d 為 -1, 那麼這個 key 不會過期

實現過程:

  1. RWMutex.Lock
  2. 設定過期時間, 將 value 放入 map 中
  3. RWMutex.Unlock

還有另外幾個衍生函式: SetDefault, Add, Replace, 這裡就不做具體介紹

Get go-cache 最重要的函式

func (c *cache) Get(k string) (interface{}, bool) {
	c.mu.RLock()
	// "Inlining" of get and Expired
	item, found := c.items[k]
	if !found {
		c.mu.RUnlock()
		return nil, false
	}
	if item.Expiration > 0 {
		if time.Now().UnixNano() > item.Expiration {
			c.mu.RUnlock()
			return nil, false
		}
	}
	c.mu.RUnlock()
	return item.Object, true
}
  1. RWMutex.RLock
  2. 判斷是否存在
  3. 判斷是否過期
  4. RLock.RUnlock

Increment/Decrement

go-cache 對數值型別的值是比較友好的, 提供大量函式 Increment, IncrementFloat等函式, 能夠輕鬆對記憶體中的各種數值進行加減, 其實現也簡單

func (c *cache) IncrementUint16(k string, n uint16) (uint16, error) {
	c.mu.Lock()
	v, found := c.items[k]
	if !found || v.Expired() {
		c.mu.Unlock()
		return 0, fmt.Errorf("Item %s not found", k)
	}
	rv, ok := v.Object.(uint16)
	if !ok {
		c.mu.Unlock()
		return 0, fmt.Errorf("The value for %s is not an uint16", k)
	}
	nv := rv + n
	v.Object = nv
	c.items[k] = v
	c.mu.Unlock()
	return nv, nil
}
  1. RWMutex.Lock
  2. 判斷某個 key 在 map 中是否存在
  3. 判斷是否這個 key 是否過期
  4. 對這個值加 n
  5. RWMutex.Unlock

落盤/恢復方案

go-cache 自帶落盤/恢復方案, 將記憶體中的值進行落盤, 同時將檔案中的內容恢復. 不過我感覺這個功能挺雞肋的, 沒必要在生產環境中使用. 這裡就不做過多的介紹了.

go-cache 過期清理方案


func (c *cache) DeleteExpired() {
	log.Printf("start check at:%v", time.Now())
	var evictedItems []keyAndValue
	now := time.Now().UnixNano()
	c.mu.Lock()
	for k, v := range c.items {
		// "Inlining" of expired
		if v.Expiration > 0 && now > v.Expiration {
			ov, evicted := c.delete(k)
			if evicted {
				evictedItems = append(evictedItems, keyAndValue{k, ov})
			}
		}
	}
	c.mu.Unlock()
	for _, v := range evictedItems {
		c.onEvicted(v.key, v.value)
	}
}

func (j *janitor) Run(c *cache) {
	ticker := time.NewTicker(j.Interval)
	for {
		select {
		case <-ticker.C:
			c.DeleteExpired()
		case <-j.stop:
			ticker.Stop()
			return
		}
	}
}

func runJanitor(c *cache, ci time.Duration) {
	j := &janitor{
		Interval: ci,
		stop:     make(chan bool),
	}
	c.janitor = j
	go j.Run(c)
}

func newCacheWithJanitor(de time.Duration, ci time.Duration, m map[string]Item) *Cache {
	c := newCache(de, m)
	// This trick ensures that the janitor goroutine (which--granted it
	// was enabled--is running DeleteExpired on c forever) does not keep
	// the returned C object from being garbage collected. When it is
	// garbage collected, the finalizer stops the janitor goroutine, after
	// which c can be collected.
	C := &Cache{c}
	if ci > 0 {
		runJanitor(c, ci)
		runtime.SetFinalizer(C, stopJanitor)
	}
	return C
}

可以看到 go-cache 每過一段時間(j.Interval, 這個值也是通過 go-cache.New 設定), 就會啟動清理工作.

清理時原理:

  1. RWMutex.Lock()
  2. 遍歷整個map, 檢查 map 中的 value 是否過期
  3. RWMutex.Unlock()

同時, 還利用了 runtime.SetFinalizer 在 go-cache 生命週期結束時, 主動完成對過期清理協程的終止

原始碼分析總結

遍覽整個 go-cache 原始碼, 會發現 go-cache 完全靠著 RWMutex 保證資料的正確性.

考慮下面的問題:

  1. 當 go-cache.New() 時設定的定時清理的時間過長, 同時 Set 的 key 的過期時間比較長, 這樣會不會導致 go-cache.map 中的元素過多?
  2. 會不會當清理啟動時, 鎖定了 go-cache.map (注意這個時候是寫鎖), 由於 go-cache.map 中元素過多, 導致 map 一直被鎖定, 那麼這個時候所有的 Set 函式是不是就會產生 Lock 競爭?
  3. 使用 go-cache 的時候, 當某個介面的 QPS 很高, 程式裡由於使用問題, 將某些不該往 go-cache 存的 value 也存了進去, 那麼會不會導致 Set 之間的 Lock 競爭呢?

場景還原

利用下面的程式可以輕鬆還原上面的問題場景. 上面提出的問題, 都會造成 go-cache lock 競爭. 這裡利用 pprof 檢視程式的指標

var goroutineNums = flag.Int("gn", 2, "goroutine nums")
func main() {
	flag.Parse()
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	rand.Seed(time.Now().Unix())
	lc := cache.New(time.Minute*5, time.Minute*2)
	log.Printf("start at:%v", time.Now())
	aaaKey := "aaa:%d:buy:cnt"
	log.Println("set run over")

	for i := 0; i < *goroutineNums; i++ {
		go func(idx int) {
			for {
				key := fmt.Sprintf(aaaKey, rand.Int())
				newKey := fmt.Sprintf("%s:%d", key, rand.Int())
				v := rand.Int()
				lc.Set(newKey, v, time.Millisecond)
			}
		}(i)
	}

	// 檢視 go-cache 中 key 的數量
	go func() {
		ticker := time.NewTicker(time.Second)
		for {
			select {
			case <-ticker.C:
				log.Printf("lc size:%d", lc.ItemCount())
			}
		}
	}()
	select {}
}

模擬介面高QPS

./go-cache-test -gn 2000
2020/03/12 00:32:33 start at:2020-03-12 00:32:33.949073 +0800 CST m=+0.001343027
2020/03/12 00:32:34 lc size:538398
2020/03/12 00:32:35 lc size:1149109

high-qps

瞬間就會出現鎖競爭

模擬 go-cache 啟動清理時的情形

./go-cache-test -gn 2   
2020/03/12 00:37:33 start at:2020-03-12 00:37:33.171238 +0800 CST m=+0.001457393
...
2020/03/12 00:40:35 lc size:54750220
2020/03/12 00:40:35 start clear at:2020-03-12 00:40:35.103586 +0800 CST m=+120.005547323
2020/03/12 00:41:51 lc size:33
2020/03/12 00:41:51 lc size:50

clear

會看到當清理 map 的時候, 如果 map 中的資料過多就會造成 Lock 競爭, 造成其他資料無法寫入 map

總結

我使用的問題

背景: 某介面 QPS 有點高

  1. 當時考慮到使用者購買狀態(這個狀態可能隨時變化)如果能夠在本地快取中快取 10s, 那麼使用者再次點進來的時候能從本地取了, 就造成大量的資料都寫入了 map 中
  2. 由於介面 QPS 比較高, 設定使用者購買狀態時就可能造成競爭, 造成介面響應超時

go-cache 使用注意點

  1. 儘量存放那些相對不怎麼變化的資料, 適用於所有的 local cache(包括 map, sync.map)
  2. go-cache 的過期檢查時間要設定相對較小, 也不能過小
  3. 那些高 QPS 的介面儘量不要去直接 Set 資料, 如果必須 Set 可以採用非同步操作
  4. 監控 go-cache 裡面 key 的數量, 如果過多時, 需要及時調整引數

資料

  1. go-cache
  2. bigcache
  3. freecache
  4. runtime.SetFinalizer

相關文章