Table of Contents

1. 前言

本文是Go语言系列文章Golang Notes的其中一篇,完整的文章列表请去总章查看。

Goroutine或者说Go程是Go语言的高性能关键。常见的高级语言比如说node、php这种,天生就是单进程单线程的,如果需要充分利用CPU,就需要启动多个进程进行集群管理。即便如此,在多个进程之间如何进行数据交换、进行业务协作又是一个基本上无解的头痛问题。而像Java这种,虽然用的是单个进程中的多线程,但因语言本身及线程设计本质的问题,开发体验仍旧说不上好。

Go为什么能这么快就火起来,第一是因为它本身的性能很好,能满足各种需求,另一个就是Goroutine了,可以说是Go的灵魂。在不增加程序复杂度的情况下,马上就能将所有的物理核心都跑满利用起来的,横向过一遍也就只有Go了。

但世上无银弹,Goroutine虽然好用消耗小,但使用不当仍旧会出问题,所以这里就需要理解其原理,并知道如何profiling找问题。

2. GPM & 原理

这部分的文章实在是太多了,基本上看完或者选择性看完(最重要的是3和4)下面几篇,就OK了:

几点记住就好:

  • G是任务,全局有一个队列,每个P还有自己的队列
  • P是逻辑处理器,由P来处理G
  • M是物理处理器(实际上是Go应用程序里的线程),P会和M绑定,得到执行的实体
  • M最终会通过操作系统调度,在CPU上得到运行

3. Profiling

pprof web

继续建议使用基于WEB的入口的方式进行查看:Golang Memory#5.3.3 runtime/pprof web。此外,由于Goroutine一般数量巨大,不像CPU和内存检查的是点,goroutine更多的时候是要把握一个状态(面),因此更建议使用pprof的WEB UI来进行观察。入口在:http://127.0.0.1:8080/debug/pprof/goroutine

e.g

$ go tool pprof -http=:8899 http://127.0.0.1:8080/debug/pprof/goroutine
Fetching profile over HTTP from http://127.0.0.1:8080/debug/pprof/goroutine
Saved profile in /Users/Jonathan/pprof/pprof.goroutine.001.pb.gz

在Profile的分析结果里,一般会看到gopark这个东西,这个在之前的几篇文章里都没怎么提到过(当然最细节的那篇是有的)。这里可以再看下:

在第一篇里还可以顺道看下自旋(spinning)的概念。

测试代码这里就不帖了,写起来实在是太简单,做个循环,起一点goroutine就好。

GODEBUG=schedtrace=1000

如果需要查看Go调度器当前状态:使用GODEBUG=schedtrace=...,第二个等号后面给时间间隔,单位为毫秒。

e.g

$ GODEBUG=schedtrace=1000 go run goroutine.go
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0 0 0 0 0]
# command-line-arguments
SCHED 0ms: gomaxprocs=8 idleprocs=5 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0 0 0 0 0]
# command-line-arguments
SCHED 0ms: gomaxprocs=8 idleprocs=5 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 1000ms: gomaxprocs=8 idleprocs=8 threads=22 spinningthreads=0 idlethreads=15 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 1010ms: gomaxprocs=8 idleprocs=0 threads=12 spinningthreads=0 idlethreads=1 runqueue=33 [1 1 0 2 2 1 1 2]
SCHED 2010ms: gomaxprocs=8 idleprocs=8 threads=22 spinningthreads=0 idlethreads=15 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 2022ms: gomaxprocs=8 idleprocs=0 threads=12 spinningthreads=0 idlethreads=1 runqueue=36 [1 1 0 1 0 2 2 0]
SCHED 3019ms: gomaxprocs=8 idleprocs=8 threads=22 spinningthreads=0 idlethreads=15 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 3027ms: gomaxprocs=8 idleprocs=0 threads=12 spinningthreads=0 idlethreads=1 runqueue=36 [1 1 1 1 0 1 1 0]
SCHED 4028ms: gomaxprocs=8 idleprocs=8 threads=22 spinningthreads=0 idlethreads=15 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 4034ms: gomaxprocs=8 idleprocs=0 threads=12 spinningthreads=0 idlethreads=1 runqueue=31 [1 0 4 4 1 0 1 0]
SCHED 5037ms: gomaxprocs=8 idleprocs=8 threads=22 spinningthreads=0 idlethreads=15 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 5037ms: gomaxprocs=8 idleprocs=0 threads=12 spinningthreads=0 idlethreads=1 runqueue=22 [3 3 3 0 3 2 3 3]
SCHED 6041ms: gomaxprocs=8 idleprocs=8 threads=22 spinningthreads=0 idlethreads=15 runqueue=0 [0 0 0 0 0 0 0 0]
...

字段说明:

  • SCHED:标识该输出信息为goroutine scheduler的输出
  • 5037ms:从程序启动到输出这行日志的时间
  • gomaxprocs:P的数量
  • idleprocs:idle状态的P的数量
  • threads:操作系统threads的数量,包含scheduler使用的m数量,加上runtime自用的类似sysmon这样的thread的数量
  • spinningthreads:处于自旋状态的操作系统thread数量
  • idlethread:处于idle状态的操作系统thread的数量
  • runqueue=22:go scheduler全局队列中G的数量
  • [3 3 3 0 3 2 3 3]:8个P的local queue中的G的数量

通过这个输出可以很清晰看到goroutine的整体状态,特别是调度的状态,到底有没有跑满CPU,到底有没有空闲的线程,任务调度整体是不是平滑的,等等。可以说是非常有用。

如果在GODEBUG中再加上,scheddetail=1的话,则会给出更多的细节:每个G、M和P的详细调度信息。

e.g

$ GODEBUG=schedtrace=1000,scheddetail=1 go run goroutine.go
...
# command-line-arguments
SCHED 0ms: gomaxprocs=8 idleprocs=5 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=0 syscalltick=0 m=3 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=1 syscalltick=0 m=2 runqsize=0 gfreecnt=0
  P2: status=1 schedtick=0 syscalltick=0 m=4 runqsize=0 gfreecnt=0
  P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P4: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P5: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P6: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P7: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M4: p=2 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=true blocked=false lockedg=-1
  M3: p=0 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M2: p=1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=true blocked=false lockedg=-1
  M1: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M0: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=1
  G1: status=1(chan receive) m=-1 lockedm=0
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=0 syscalltick=0 m=0 runqsize=0 gfreecnt=0
  P1: status=1 schedtick=0 syscalltick=0 m=3 runqsize=0 gfreecnt=0
  P2: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P4: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P5: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P6: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P7: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M3: p=1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=0 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=1
  G1: status=1() m=-1 lockedm=0
  G17: status=6() m=1 lockedm=1
  G2: status=1() m=-1 lockedm=-1
...

4. Blocking

阻塞的事情在这里顺道提一笔,毕竟阻塞和goroutine还是有很深的关系的,很多时候我们的debug就是要找死循环或死锁的goroutine。如果需要查看程序当中的阻塞情况(主要是竞争锁),一样可以使用pprof,入口在:go tool pprof http://127.0.0.1:8080/debug/pprof/block

资料

EOF