讀鎖調(diào)度導(dǎo)致高延遲的 case 一例

在給某個項目做長時間極限壓測的時候，經(jīng)常會出現(xiàn)壓幾小時不出問題，突然就崩了(延遲大幅上升)的情況。

查看監(jiān)控發(fā)現(xiàn)崩的時候 goroutine 突然漲起來了，那么可以用我之前開發(fā)的問題診斷工具了，配置下面的策略：若 goroutine 突然開始暴漲，則將 goroutine 文本 dump 下來。對這個診斷工具不了解的，可以看看我之前寫的 無人值守的自動 dump-2[1] 和 無人值守的自動 dump[2]。

代碼集成好之后再壓，發(fā)現(xiàn)崩潰時，總是有很多卡在鎖上的 goroutine：

10760 @ 0x42f81f 0x4401d9 0x4401af 0x43ff4d 0x474df9 0x95709a 0x952d0d 0x17466fc 0x17462c4 0x174c8a8 0x174c88a 0x174e308 0x1755b78 0x1749432 0x17588e8 0xf90a54 0xc9670d 0x45d061
# 0x43ff4c sync.runtime_SemacquireMutex+0x3c    /Users/xargin/sdk/go1.12.17/src/runtime/sema.go:71
# 0x474df8 sync.(*Mutex).Lock+0x108     /Users/xargin/sdk/go1.12.17/src/sync/mutex.go:134
# 0x957099 github.com/rcrowley/go-metrics.(*UniformSample).Update+0x39 /Users/xargin/mosn/vendor/github.com/rcrowley/go-metrics/sample.go:508
# 0x952d0c github.com/rcrowley/go-metrics.(*StandardHistogram).Update+0x3c /Users/xargin/mosn/vendor/github.com/rcrowley/go-metrics/histogram.go:199
.....這下面就是一堆業(yè)務(wù)代碼了......

1 @ 0x42f81f 0x4401d9 0x4401af 0x43ff4d 0x474df9 0x504a3d 0x5040ba 0x5040ac 0x957187 0x957172 0x952d0d 0x17465d0 0x17462c4 0x174c8a8 0x174c88a 0x174e308 0x1755b78 0x1749432 0x17588e8 0xf90a54 0xc9670d 0x45d061
# 0x43ff4c sync.runtime_SemacquireMutex+0x3c    /Users/xargin/sdk/go1.12.17/src/runtime/sema.go:71
# 0x474df8 sync.(*Mutex).Lock+0x108     /Users/xargin/sdk/go1.12.17/src/sync/mutex.go:134
# 0x504a3c math/rand.(*lockedSource).Int63+0x2c    /Users/xargin/sdk/go1.12.17/src/math/rand/rand.go:380
# 0x5040b9 math/rand.(*Rand).Int63+0x69     /Users/xargin/sdk/go1.12.17/src/math/rand/rand.go:85
# 0x5040ab math/rand.(*Rand).Int63n+0x5b     /Users/xargin/sdk/go1.12.17/src/math/rand/rand.go:117
# 0x957186 math/rand.Int63n+0x126      /Users/xargin/sdk/go1.12.17/src/math/rand/rand.go:319
# 0x957171 github.com/rcrowley/go-metrics.(*UniformSample).Update+0x111 /Users/xargin/mosn/vendor/github.com/rcrowley/go-metrics/sample.go:514
# 0x952d0c github.com/rcrowley/go-metrics.(*StandardHistogram).Update+0x3c /Users/xargin/mosn/vendor/github.com/rcrowley/go-metrics/histogram.go:199
....這下面是一堆業(yè)務(wù)代碼了.....

如果分析原因的話，其實不難理解，極限壓測時 CPU 利用率都比較高 90%+，這時鎖沖突就是會導(dǎo)致整個服務(wù)因為鎖沖突而直接崩掉(goroutine 暴漲 OOM 之類的，或者延遲大幅上升，不可用)。

但問題是為什么是壓了一段時間后才崩，而不是一開始就崩呢，壓測平臺給服務(wù)的壓力在這個期間并沒有什么變化，看監(jiān)控也沒有 tcp retrans 之類的事件發(fā)生。

正好最近在一個朋友群，有前同事拉出了我之前寫的一篇文章：一個和 rlock 有關(guān)的小故事[3]來鞭尸，當(dāng)時寫的比較粗糙，后來被網(wǎng)友打臉：又一個和 rlock 有關(guān)的小故事[4]，并且有網(wǎng)友在評論區(qū)指出了一些問題，我把改進后的 demo 貼在這里：

     1 package main
     2 
     3 import (
     4  "fmt"
     5  "os"
     6  "runtime/trace"
     7  "sync"
     8  "sync/atomic"
     9  "time"
    10 )
    11 
    12 var mlock sync.RWMutex
    13 var wg sync.WaitGroup
    14 
    15 func main() {
    16  trace.Start(os.Stderr)
    17  defer trace.Stop()
    18  wg.Add(100)
    19 
    20  for i := 0; i < 100; i++ {
    21   go gets()
    22  }
    23 
    24  wg.Wait()
    25  if a > 0 {
    26   fmt.Println("here", a)
    27  }
    28 }
    29 
    30 func gets() {
    31  for i := 0; i < 100000; i++ {
    32   get(i)
    33  }
    34  wg.Done()
    35 }
    36 
    37 var a int64
    38 
    39 func get(i int) {
    40  beginTime := time.Now()
    41  mlock.RLock()
    42  tmp1 := time.Since(beginTime).Nanoseconds() / 1000000
    43  if tmp1 > 100 { // 超過100ms
    44   atomic.AddInt64(&a, 1)
    45  }
    46  mlock.RUnlock()
    47 }

當(dāng)控制臺有輸出時，把 trace 記錄下來，可以發(fā)現(xiàn) RLock 取鎖成功之后，time.Since 函數(shù)調(diào)用時被協(xié)作式搶占調(diào)度出去了。這里搶占的原因是函數(shù)擴棧，不是因為 syscall。

這個結(jié)論能給我們一些參考意義，在 CPU 使用率較高時，獲取 RLock 的 goroutine 還是有一定概率被搶占的，這種搶占對于我們的服務(wù)是有較大的破壞性的：

Authors of parallel programs have known for decades that performance can suffer badly if a thread is preempted while holding a lock; this is sometimes referred to as inopportune preemption.

也就是說，如果在持鎖期間被搶占，那么其它 goroutine 就必須等這個 goroutine 從全局隊列里重新被調(diào)度回來，并執(zhí)行完它的臨界區(qū)，才能搶鎖成功。

假如這時候來一個 write lock，那就有意思了。而因為這種調(diào)度本身就具有一定的隨機性，所以如果真的是碰上了，也確實很難定位。

具體的現(xiàn)象是，平穩(wěn)了很長時間，突然它就崩了！