简介
我喜欢 Go 语言的一个原因就是因为它可以生成分析和调试信息。当程序在执行的时候 Go 有一个特殊的环境变量 GODEBUG,它在运行阶段可以生成调试信息。你可以获取程序回收器和调度器的概要信息以及详细的信息。更主要的是你不需要添加任何的额外工作重新编译就可以完成调试
在这篇文章里,我将通过一个简单的 Go 程序演示如果使用调度跟踪信息。如果你对调度器有一定的了解那么它对你是用的。我建议先阅读下面两篇文章:
并发、goroutines 和 GOMAXPROCS
http://www.goinggo.net/2014/01/concurrency-goroutines-and-gomaxprocs.html
调度器
http://morsmachine.dk/go-scheduler
代码部分
我们将用一个简单的程序验证和解释 GODEBUG 的结果:
清单 1
package main
import (
"sync"
"time"
)
func main() {
var wg sync.WaitGroup
wg.Add(10)
for i := 0; i < 10; i++ {
Go work(&wg)
}
wg.Wait()
// Wait to see the global run queue deplete.
time.Sleep(3 * time.Second)
}
func work(wg *sync.WaitGroup) {
time.Sleep(time.Second)
var counter int
for i := 0; i < 1e10; i++ {
counter++
}
wg.Done()
}
清单 1 中的例子是为了演示运行时调试器给我们的调试信息。在第 12 秒 for 循环进行 10 次 goroutines。然后主函数在第 16 行的时候等待所有 goroutines 执行完成。在第 22 行 work 函数里面先 sleep 一秒然后 counter 变量 ++ 执行一百亿次。当 for 循环执行完成后调用 Done 方法最后 return。
在设置 GODEBUG 之前,先用 go build 编译代码。这个变量由运行时获取,因此运行 Go 命令也将产生跟踪输出。如果 GODEBUG 结合 go run 使用,那么你将看到运行之前的跟踪调试信息。
现在我们使用 go build 编译上面的例子,这样我们就可以携带 GODEBUG 选项运行例子了:
go build example.go
调度器跟踪摘要信息
schedtrace 选项使代码在运行时每隔 X 秒输出一行调度器的状态信息到标准错误输出。现在我们运行程序并且设置 GODEBUG 选项:
GOMAXPROCS=1 GODEBUG=schedtrace=1000 ./example
当程序运行起来,我们就可以看到跟踪信息。程序本身没有输出任何的标准输出和标准错误输出,所以我们可以专注在跟踪信息上。现在我们看最开始的两条跟踪信息:
SCHED 0ms: Gomaxprocs=1 idleprocs=0 threads=2 spinningthreads=0 idlethreads=0
runqueue=0 [1]
SCHED 1009ms: Gomaxprocs=1 idleprocs=0 threads=3 spinningthreads=0 idlethreads=1
runqueue=0 [9]
现在我们来分析每个字段的意思并理解在例子中的作用:
1009ms : 时间是以毫秒为单位,表示了从程序开始运行的时间。这个是第一秒的跟踪信息。
gomaxprocs=1 : 配置的最大的处理器的个数
本程序只配置了一个
更多说明:
这里的处理器是逻辑上的处理器而非物理上的处理器。调度器在这些逻辑处理器上运行 goroutines,这些逻辑处理器通过所附着的操作系统线程绑定在物理处理器上的。 操作系统将在可见的物理存储器上调度线程。
threads=3 : 运行时管理的线程个数。有三个线程存在,一个是给处理器使用,其他两个是被运行时使用。
idlethreads=1 : 空闲的线程个数。一个空闲,两个正在运行。
idleprocs=0 : 空闲的处理器个数。这里空闲个数为 0,有一个运行中。
runqueue=0 : 在全局运行队列中等待的 goroutinue 数量。所有可运行的 goroutinue 都被移到了本地的运行队列中。
[9] : 本地运行队列中等待的 goroutine 数量。当前有 9 个 goroutine 在本地运行队列等待。
在运行时的摘要信息里面给了我们很多非常有用的信息。我们从运行的一秒的标记里面可以看到跟踪的信息。我们可以看到一个 gorountine 如何运行,其它 9 个 goroutine 都在 local run queue 中等待。
图 1
从图一中可以看到处理器用字母 "P" 代表,线程使用字母 "M" 代码,goroutines 使用字母 "G" 代表。我们可以看到当 runqueue 的值为 0 时,全局的 run queue 是空的。处理器将会把 gorountine 运行在 idleprocs 为 0 的上面运行。我们运行的其他九个 goroutine 仍然在等待。
那如果有多个处理器的时候,那我们该如何跟踪呢?那我们再运行一次程序并添加 GOMAXPROCS 选项,看看会输出什么跟踪信息:
GOMAXPROCS=2 GODEBUG=schedtrace=1000 ./example
SCHED 0ms: gomaxprocs=2 idleprocs=1 threads=2 spinningthreads=0
idlethreads=0 runqueue=0 [0 0]
SCHED 1002ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=1
idlethreads=1 runqueue=0 [0 4]
SCHED 2006ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=0 [4 4]
…
SCHED 6024ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=2 [3 3]
…
SCHED 10049ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=4 [2 2]
…
SCHED 13067ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=6 [1 1]
…
SCHED 17084ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=8 [0 0]
…
SCHED 21100ms: gomaxprocs=2 idleprocs=2 threads=4 spinningthreads=0
idlethreads=2 runqueue=0 [0 0]
我们重点看一下第二秒的信息:
SCHED 2002ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=0 [4 4]
2002ms : This is the trace for the 2 second mark.
gomaxprocs=2 : 2 processors are configured for this program.
threads=4 : 4 threads exist. 2 for processors and 2 for the runtime.
idlethreads=1 : 1 idle thread (3 threads running).
idleprocs=0 : 0 processors are idle (2 processors busy).
runqueue=0 : All runnable goroutines have been moved to a local run queue.
[4 4] : 4 goroutines are waiting inside each local run queue.
...
图 2
我们看一下第二秒跟踪信息在图 2 中的信息,我们可以看到一个 goroutine 在每个处理器中是如何运行的。并且我们可以看到 8 个 goroutine 在 local run queues 中等待,每个 local run queues 各四个。在跟踪信息的第六秒发生了改变:
SCHED 6024ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=2 [3 3]
idleprocs=0 : 0 processors are idle (2 processors busy).
runqueue=2 : 2 goroutines returned and are waiting to be terminated.
[3 3] : 3 goroutines are waiting inside each local run queue.
图 3:
当到第六秒的时候发生了变化。从图 3 中有两个 goroutine 完成工作之后被移到了 global run queue 里面,并且我们仍然有两个 goroutine 在运行。每个 processor 各运行一个,在每个 local run queue 里面各有三个在等待。
注释:
在很多情况下,goroutine 运行完成之后并不会被移到全局的 run queue 中。这个例子创建的条件比较特殊。因为这个例子的 for 循环运行了 10 秒多的时间但是没有任何的函数调用。10 秒是调度的次数在调度器里面。在执行 10 秒后,调度器尝试先去取 goroutine。但是这些 goroutine 不能被占用,因为它们没有调用任何的函数。在这种情况下,一旦 goroutine 调用 wg.Done,这个 goroutine 将立即被占用,然后移到全局的 run queue 中。
当到第 17 秒的时候,我们可以看到最后两个 goroutine 都在运行了:
SCHED 17084ms: Gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=8 [0 0]
idleprocs=0 : 0 processors are idle (2 processors busy).
runqueue=8 : 8 goroutines returned and are waiting to be terminated.
[0 0] : No goroutines are waiting inside any local run queue.
图 4:
在图 4 中,我们可以看到 8 个 goroutines 在 global run queue 中,还有两个仍然在运行。这个时候每个 local run queue 已经空了。最终的跟踪信息在第 12 秒结束:
SCHED 21100ms: Gomaxprocs=2 idleprocs=2 threads=4 spinningthreads=0
idlethreads=2 runqueue=0 [0 0]
idleprocs=2 : 2 processors are idle (0 processors busy).
runqueue=0 : All the goroutines that were in the queue have been terminated.
[0 0] : No goroutines are waiting inside any local run queue.
图 5:
至此,所有的 goroutine 都执行完了并且已经结束。
详细的跟踪信息
概要的跟踪信息是非常有用的,但是有的时候你需要更详细的信息。如果需要更详细的每个处理器,线程的或者 goroutine 的跟踪信息我们可以添加 scheddetail 这个选项。我们再一次运行程序,设置 GODEBUG 选项获取更详细的跟踪信息:
GOMAXPROCS=2 GODEBUG=schedtrace=1000,scheddetail=1 ./example
下面是第四秒的输出信息:
SCHED 4028ms: Gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=2 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
P0: status=1 schedtick=10 syscalltick=0 m=3 runqsize=3 gfreecnt=0
P1: status=1 schedtick=10 syscalltick=1 m=2 runqsize=3 gfreecnt=0
M3: p=0 curg=4 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M2: p=1 curg=10 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M1: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M0: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
G1: status=4(semacquire) m=-1 lockedm=-1
G2: status=4(force gc (idle)) m=-1 lockedm=-1
G3: status=4(GC sweep wait) m=-1 lockedm=-1
G4: status=2(sleep) m=3 lockedm=-1
G5: status=1(sleep) m=-1 lockedm=-1
G6: status=1(stack growth) m=-1 lockedm=-1
G7: status=1(sleep) m=-1 lockedm=-1
G8: status=1(sleep) m=-1 lockedm=-1
G9: status=1(stack growth) m=-1 lockedm=-1
G10: status=2(sleep) m=2 lockedm=-1
G11: status=1(sleep) m=-1 lockedm=-1
G12: status=1(sleep) m=-1 lockedm=-1
G13: status=1(sleep) m=-1 lockedm=-1
G17: status=4(timer goroutine (idle)) m=-1 lockedm=-1
概要部分基本相同,但是有了关于处理器,线程以及 goroutine 更详细的信息。我们看看关于处理器的信息:
P0: status=1 schedtick=10 syscalltick=0 m=3 runqsize=3 gfreecnt=0
P1: status=1 schedtick=10 syscalltick=1 m=2 runqsize=3 gfreecnt=0
P 代表一个处理器。因为 GOMAXPROCS 被设置为 2,我们可以看到处理器的列表。下来我们看看线程:
M3: p=0 curg=4 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M2: p=1 curg=10 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M1: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M0: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
M 代码一个线程,因为 threadsb 被设置为 4,所以我们能看到 4 个线程的详细信息。并且线程详细信息里面展示了线程所在的处理器:
P0: status=1 schedtick=10 syscalltick=0 m=3 runqsize=3 gfreecnt=0
M3: p=0 curg=4 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0
spinning=0 blocked=0 lockedg=-1
这里展示了线程 M3 是如何绑定在处理器 P0 上的。这个信息在 P 和 M 的跟踪信息里面都有。
G 代码一个 goroutine。在第四秒的时候我们可以看到有 14 个 goroutine 存在,有 17 个 goroutine 被创建。我们之所以知道总共的 goroutine 的个数是因为最后在 G 列表里面绑定的数字:
G17: status=4(timer goroutine (idle)) m=-1 lockedm=-1
如果成行继续创建 goroutine,我们就可以看到这个数字将呈线性的增长。如果这个程序是拦截 Web 请求的例子,那么我们可以用这个数字来确认请求的拦截次数。只有当拦截请求期间不再创建任何的 goroutine,这个才会被关闭。
下面我们看看在 main 方法里面的 goroutine:
G1: status=4(semacquire) m=-1 lockedm=-1
30 wg.Done()
我们可以看到在 main 方法中 goroutine 的状态为 4,状态被锁定在 semacquire 状态,这个状态表示等待调用。
为了更好的理解剩下的跟踪信息,先来了解一下状态代码的意思。下面是状态值列表,这些声明在 runtime 包的头文件里面的:
status: http://golang.org/src/runtime/
Gidle, // 0
Grunnable, // 1 runnable and on a run queue
Grunning, // 2 running
Gsyscall, // 3 performing a syscall
Gwaiting, // 4 waiting for the runtime
Gmoribund_unused, // 5 currently unused, but hardcoded in gdb scripts
Gdead, // 6 goroutine is dead
Genqueue, // 7 only the Gscanenqueue is used
Gcopystack, // 8 in this state when newstack is moving the stack
对照他们的状态我们能更好的理解我们创建的 10 个 goroutine 都在做什么。
// goroutines running in a processor. (idleprocs=0)
G4: status=2(sleep) m=3 lockedm=-1 – Thread M3 / Processor P0
G10: status=2(sleep) m=2 lockedm=-1 – Thread M2 / Processor P1
// goroutines waiting to be run on a particular processor. (runqsize=3)
G5: status=1(sleep) m=-1 lockedm=-1
G7: status=1(sleep) m=-1 lockedm=-1
G8: status=1(sleep) m=-1 lockedm=-1
// goroutines waiting to be run on a particular processor. (runqsize=3)
G11: status=1(sleep) m=-1 lockedm=-1
G12: status=1(sleep) m=-1 lockedm=-1
G13: status=1(sleep) m=-1 lockedm=-1
// goroutines waiting on the global run queue. (runqueue=2)
G6: status=1(stack growth) m=-1 lockedm=-1
G9: status=1(stack growth) m=-1 lockedm=-1
基于对 scheduler 的简单了解以及对我们例子程序的了解,我们对程序如何被 scheduled,每个处理器的状态是什么,线程以及 goroutine 等信息都有了全面的了解。
总结:
GODEBUG 是一个非常有效的手段去跟踪程序的执行。它帮助你了解很多程序的执行详细信息。如果你想了解更多,从写一些简单的例子入手,你可以预测它可能来自于 scheduler 的跟踪信息。在尝试去看一些复杂例子的跟踪信息之前,先学会如何预测。
via: https://www.ardanlabs.com/blog/2015/02/scheduler-tracing-in-go.html
作者:William Kennedy 译者:amei 校对:polaris1119
本文由 GCTT 原创编译,Go语言中文网 荣誉推出