一种持锁被调度的情况

在给某个项目做长时间极限压测的时候,经常会出现压几小时不出问题,突然就崩了的情况。

查看监控发现崩的时候 goroutine 突然涨起来了,那么可以用我之前开发的问题诊断工具了,配置下面的策略:若 goroutine 突然开始暴涨,则将 goroutine 文本 dump 下来。对这个诊断工具不了解的,可以看看我之前写的 无人值守的自动 dump-2无人值守的自动 dump

代码集成好之后再压,发现崩溃时,总是有很多卡在锁上的 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
.....这下面就是一堆业务代码了......

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
....这下面是一堆业务代码了.....

如果分析原因的话,其实不难理解,极限压测时 CPU 利用率都比较高 90%+,这时锁冲突就是会导致整个服务因为锁冲突而直接崩掉(goroutine 暴涨 OOM 之类的,或者延迟大幅上升,不可用)。

但问题是为什么是压了一段时间后才崩,而不是一开始就崩呢,压测平台给服务的压力在这个期间并没有什么变化,看监控也没有 tcp retrans 之类的事件发生。

正好最近在一个朋友群,有前同事拉出了我之前写的一篇文章:一个和 rlock 有关的小故事,当时写的比较粗糙,后来被网友打脸:又一个和 rlock 有关的小故事,并且有网友在评论区指出了一些问题,我把改进后的 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	}

当控制台有输出时,把 trace 记录下来,可以发现 RLock 取锁成功之后,time.Since 函数调用时被协作式抢占调度出去了。这里抢占的原因是函数扩栈,不是因为 syscall。

这个结论能给我们一些参考意义,在 CPU 使用率较高时,获取 RLock 的 goroutine 还是有一定概率被抢占的,这种抢占对于我们的服务是有一定的破坏性的:

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 从全局队列里重新被调度回来,并执行完它的临界区,才能抢锁成功。

假如这时候来一个 write lock,那就有意思了。而因为这种调度本身就具有一定的随机性,所以如果真的是碰上了,也确实很难定位。