Golang又一个和RLock有关的小故事

  • 2019 年 12 月 26 日
  • 笔记

一. 背景

前几天看了一篇golang的文章一个和RLock有关的小故事, 发现作者得到的结论是错误的, 实际涉及内容比作者讲解的多一些。

二. 错误结论

先看下面的代码, 此段代码表现为sync.RWMutex的RLock操作效率极低。

package main  import (  	"fmt"  	"os"  	"runtime/trace"  	"sync"  	"time"  )  var mlock sync.RWMutex  var wg sync.WaitGroup  func main() {  	trace.Start(os.Stderr)  	defer trace.Stop()  	wg.Add(100)  	for i := 0; i < 100; i++ {  		go gets()  	}  	wg.Wait()  }  func gets() {  	for i := 0; i < 100000; i++ {  		get(i)  	}  	wg.Done()  }  func get(i int) {  	beginTime := time.Now()  	mlock.RLock()  	tmp1 := time.Since(beginTime).Nanoseconds() / 1000000  	if tmp1 > 100 { // 超过100ms就打印出来  		fmt.Println("fuck here")  	}  	mlock.RUnlock()  }

某一次的控制台输出样式:

1574766952_60_w483_h322.png

整个代码片只涉及RWMutex的RLock和RUnlock, RLock是不相互影响的, 我们可以理解为只涉及atomic.AddInt32。

但是代码执行过程偶尔打印"fuck here", 表明某些时候RLock耗时超过100ms, 这对我们来说应该是impossible。

1574766964_45_w1218_h514.jpg

作者查看某个grontinue表明是syscall blocking, 其实是正常的调度。

1574766971_55_w1208_h560.jpg

作者用go tool对trace分析得到Goroutine执行结果统计, 看到goroutine存在blocking syscall就武断的认为是syscall原因引起

作者解释原因是:goroutine在RLock后, 因为要调用time.Since(time.Now)的syscall被runtime调出, 后随缘被系统再次调度, 这个随缘可能耗时超过100ms. 但是这个结论50%是错误的, 50%是正确的 。

三. time.Now()的实现

golang的time.Now最终调用是用汇编实现的代码, 代码精简后如下。

我们从代码中可以发现得到时间用的的vdso方式的调用, 因为有些内核使用太频繁, 每次都内核调用开销太高, 就将用户态的一段内存映射到内核, 这样内核调用就转换成用户态函数调用和内存读取。

// func walltime() (sec int64,  nsec int32)  TEXT runtime·walltime(SB), NOSPLIT, $0-12  	...  	MOVQ	g(CX),  AX  	MOVQ	g_m(AX),  BX // BX unchanged by C code.  	MOVQ	0(SP),  DX  	MOVQ	DX,  m_vdsoPC(BX)  	LEAQ	sec+0(SP),  DX  	MOVQ	DX,  m_vdsoSP(BX)  	CMPQ	AX,  m_curg(BX)	// Only switch if on curg.  	...  noswitch:  	...  	MOVQ	runtime·vdsoClockgettimeSym(SB),  AX  	...      MOVQ	$0,  m_vdsoSP(BX)  	...  fallback:  	...  	MOVQ	runtime·vdsoGettimeofdaySym(SB),  AX  	...      MOVQ	$0,  m_vdsoSP(BX)  	...

walltime涉及的vdso库的解析.

var vdsoSymbolKeys = []vdsoSymbolKey{  	{"__vdso_gettimeofday",  0x315ca59,  0xb01bca00,  &vdsoGettimeofdaySym},  	{"__vdso_clock_gettime",  0xd35ec75,  0x6e43a318,  &vdsoClockgettimeSym},  }

当然上面代码阅读起来还是有点困难, 进行翻译以后就是下面的代码, vdso_clock_gettime的精度是纳秒而 vdso_gettimeofday的精度是微秒。

type timespec struct {      sec  int64      nsec int64  }    type timeval struct {      sec  int64      usec int64  }    func walltime() (sec int64,  nsec int32) {      if __vdso_clock_gettime != nil {          t := &timespec{}          __vdso_clock_gettime(CLOCK_REALTIME,  t)          return t.sec,  int32(t.nsec)      }      t := &timeval{}      __vdso_gettimeofday(t,  nil)      return t.sec,  int32(t.usec * 1000)  }

在walltime确实涉及到GPM中G和M的调度m_curg, 但是这个只是使用线程M的调度器G0的栈而已, 只因为G0的栈比普通的栈大, 而vdso调用需要的栈比较大而已。

四. syscall blocking

通过上面的分析可以看出整个time.Now()操作都是同步完成, 不涉及syscall blocking。

那文章作者的syscall blocking怎么来的呢?我们可以在本地跑一下代码, 我们选择个配置比较差的环境跑程序, trace后查看具体的阻塞goroutine的event。

1574767010_18_w1194_h424.png

生成syscall blocking图如下

1574767018_63_w396_h455.png

可以看到这个syscall blocking是因为这段代码调用标准输出打印信息导致, 追踪fmt.Println("fuck here")最终定位到下面的代码, 在代码里边存在.

func WriteFile(handle Handle,  buf []byte,  done *uint32,  overlapped *Overlapped) (err error) {  	var _p0 *byte  	if len(buf) > 0 {  		_p0 = &buf[0]  	}  	r1,  _,  e1 := Syscall6(procWriteFile.Addr(),  5,  uintptr(handle),  uintptr(unsafe.Pointer(_p0)),  uintptr(len(buf)),  uintptr(unsafe.Pointer(done)),  uintptr(unsafe.Pointer(overlapped)),  0)  	if r1 == 0 {  		if e1 != 0 {  			err = errnoErr(e1)  		} else {  			err = EINVAL  		}  	}  	return  }

函数调用的都是syscall一簇函数系列, 此系列函数还有Syscall/RawSyscall/RawSyscall6等, 这些函数在runtime中都是汇编实现, 我们抽取其中一个来进行分析, 这里边最关键的就是runtime·entersyscall和runtime·exitsyscall两个函数。

TEXT ·Syscall(SB), NOSPLIT, $0-56  	CALL	runtime·entersyscall(SB)  	...  	SYSCALL  	...  	CALL	runtime·exitsyscall(SB)  	RET  ok:  	...  	CALL	runtime·exitsyscall(SB)  	RET
  • runtime·exitsyscall粗略执行逻辑:通知系统调用时候，是会将grontinue的M的P解绑，P可以去继续获取M执行其余的是会将grontinue的M的P解绑，这样提升效率。
  • runtime·exitsyscall粗略执行逻辑: 通知调度系统, 解除grontinue与M的绑定, 将M加入到空闲队列, 将grontinue放入到全局调度队列中。

从上面的分析可以得出结论是WriteFile调用Syscall6导致syscall blocking。

五. 正确结论

在grontinue执行到下面函数中间时候被调去, 然后随缘调度, 等调度回来的时候超过100ms。

 mlock.RLock()   //here   tmp1 := time.Since(beginTime).Nanoseconds() / 1000000

六. 真正syscall blocking实验

我们来个mlock.RLock()后真实存在需要syscall blocking的操作来测试一下。

因为比较喜欢window系统所以选择window下的os.Getenv来测试。

注意在linux下os.Getenv实现和window不同。

func GetEnvironmentVariable(name *uint16,  buffer *uint16,  size uint32) (n uint32,  err error) {  	r0,  _,  e1 := Syscall(procGetEnvironmentVariableW.Addr(),  3,  uintptr(unsafe.Pointer(name)),  uintptr(unsafe.Pointer(buffer)),  uintptr(size))  	n = uint32(r0)  	if n == 0 {  		if e1 != 0 {  			err = errnoErr(e1)  		} else {  			err = EINVAL  		}  	}  	return  }

测试的部分代码逻辑如下, 我们只选择创建3个goroutine, 100个goroutine信息太多图会生成失败。

var buf bytes.Buffer  func get(i int) {  	mlock.RLock()  	env:=os.Getenv("aaa")  	if env!=""{  		env=""  	}  	buf.WriteString(env)  	mlock.RUnlock()  }

生成的goroutine调度远比没有syscall blocking的复杂。

1574767051_63_w1660_h551.png

生成syscall blocking图如下:

1574767058_85_w410_h360.png

VirMach 便宜 VPS

QNews

QNews