使用defer实现函数执行过程的跟踪
package main
func Trace(name string) func() {
println("enter:", name)
return func() {
println("exit:", name)
}
}
func foo() {
defer Trace("foo")()
bar()
}
func bar() {
defer Trace("bar")()
}
func main() {
defer Trace("main")()
foo()
}
函数调用次序:main -> foo -> bar
运行结果:
enter: main
enter: foo
enter: bar
exit: bar
exit: foo
exit: main
自动获取所跟踪函数的函数名
package main
import "runtime"
func Trace() func() {
pc, _, _, ok := runtime.Caller(1)
/* 获得当前 Goroutine 的函数调用栈上的信息
当参数为 0 时,返回的是 Caller 函数的调用者的函数信息,在这里就是 Trace 函数。
但这里需要的是 Trace 函数的调用者的信息,于是传入 1。*/
//Caller 函数有四个返回值:程序计数(pc)、对应函数所在的源文件名以及所在行数、是否能成功获取这些信息(ok)
if !ok {
panic("not found caller")
}
fn := runtime.FuncForPC(pc)
name := fn.Name()
println("enter:", name)
return func() {
println("exit:", name)
}
}
func foo() {
defer Trace()()
bar()
}
func bar() {
defer Trace()()
}
func main() {
defer Trace()()
foo()
}
运行结果:
enter: main.main
enter: main.foo
enter: main.bar
exit: main.bar
exit: main.foo
exit: main.main
上面的 Trace 函数在面对只有一个 Goroutine 的时候,还是可以支撑的,但当程序中并发运行多个 Goroutine 的时候,多个函数调用链的出入口信息输出就会混杂在一起,无法分辨。
增加Goroutine 标识
让其在输出的函数出入口信息时,带上一个在程序每次执行时能唯一区分 Goroutine 的 Goroutine ID。
Go 核心团队为了避免Goroutine ID 的滥用,故意没有将 Goroutine ID 暴露给开发者。但在 Go 标准库的 h2_bundle.go 中,有一个获取 Goroutine ID 的标准方法
// $GOROOT/src/net/http/h2_bundle.go
var http2goroutineSpace = []byte("goroutine ")
func http2curGoroutineID() uint64 {
bp := http2littleBuf.Get().(*[]byte)
defer http2littleBuf.Put(bp)
b := *bp
b = b[:runtime.Stack(b, false)]
// Parse the 4707 out of "goroutine 4707 ["
b = bytes.TrimPrefix(b, http2goroutineSpace)
i := bytes.IndexByte(b, ' ')
if i < 0 {
panic(fmt.Sprintf("No space found in %q", b))
}
b = b[:i]
n, err := http2parseUintBytes(b, 10, 64)
if err != nil {
panic(fmt.Sprintf("Failed to parse goroutine ID out of %q: %v", b, err))
}
return n
}
由于 http2curGoroutineID 不是一个导出函数,无法直接使用。将它复制出来改造一下:
// trace2/trace.go
var goroutineSpace = []byte("goroutine ")
func curGoroutineID() uint64 {
b := make([]byte, 64)
b = b[:runtime.Stack(b, false)]
// Parse the 4707 out of "goroutine 4707 ["
b = bytes.TrimPrefix(b, goroutineSpace)
i := bytes.IndexByte(b, ' ')
if i < 0 {
panic(fmt.Sprintf("No space found in %q", b))
}
b = b[:i]
n, err := strconv.ParseUint(string(b), 10, 64)
if err != nil {
panic(fmt.Sprintf("Failed to parse goroutine ID out of %q: %v", b, err))
}
return n
}
改造了两个地方。一个地方是通过直接创建一个 byte 切片赋值给 b,替代原 http2curGoroutineID 函数中从一个 pool 池获取 byte 切片的方式,另外一个是使用 strconv.ParseUint 替代了原先的 http2parseUintBytes
package main
import (
"bytes"
"fmt"
"runtime"
"strconv"
"sync"
)
var goroutineSpace = []byte("goroutine ")
func curGoroutineID() uint64 {
b := make([]byte, 64)
b = b[:runtime.Stack(b, false)]
// Parse the 4707 out of "goroutine 4707 ["
b = bytes.TrimPrefix(b, goroutineSpace)
i := bytes.IndexByte(b, ' ')
if i < 0 {
panic(fmt.Sprintf("No space found in %q", b))
}
b = b[:i]
n, err := strconv.ParseUint(string(b), 10, 64)
if err != nil {
panic(fmt.Sprintf("Failed to parse goroutine ID out of %q: %v", b, err))
}
return n
}
func Trace() func() {
pc, _, _, ok := runtime.Caller(1)
if !ok {
panic("not found caller")
}
fn := runtime.FuncForPC(pc)
name := fn.Name()
gid := curGoroutineID()
fmt.Printf("g[%05d]: enter: [%s]\n", gid, name)
return func() { fmt.Printf("g[%05d]: exit: [%s]\n", gid, name) } //%05d ID 值不足 5 位,则左补零
}
func A1() {
defer Trace()()
B1()
}
func B1() {
defer Trace()()
C1()
}
func C1() {
defer Trace()()
D()
}
func D() {
defer Trace()()
}
func A2() {
defer Trace()()
B2()
}
func B2() {
defer Trace()()
C2()
}
func C2() {
defer Trace()()
D()
}
func main() {
var wg sync.WaitGroup
wg.Add(1)
go func() {
A2()
wg.Done()
}()
A1()
wg.Wait()
}
main groutine 的调用链为A1 -> B1 -> C1 -> D
另一个Goroutine 的函数调用链为A2 -> B2 -> C2 -> D
输出结果如下:
g[00001]: enter: [main.A1]
g[00001]: enter: [main.B1]
g[00001]: enter: [main.C1]
g[00001]: enter: [main.D]
g[00001]: exit: [main.D]
g[00001]: exit: [main.C1]
g[00001]: exit: [main.B1]
g[00001]: exit: [main.A1]
g[00006]: enter: [main.A2]
g[00006]: enter: [main.B2]
g[00006]: enter: [main.C2]
g[00006]: enter: [main.D]
g[00006]: exit: [main.D]
g[00006]: exit: [main.C2]
g[00006]: exit: [main.B2]
g[00006]: exit: [main.A2]
让输出的跟踪信息更具层次感
使用一个 map 类型变量 m 来保存每个 Goroutine 当前的缩进信息:m 的 key 为 Goroutine 的 ID,值为缩进的层次。然后,考虑到 Trace 函数可能在并发环境中运行,由于map 不支持并发写,所以增加一个 sync.Mutex 实例 mu 用于同步对 m 的写操作。
代码如下:
package main
import (
"bytes"
"fmt"
"runtime"
"strconv"
"sync"
)
var goroutineSpace = []byte("goroutine ")
func curGoroutineID() uint64 {
b := make([]byte, 64)
b = b[:runtime.Stack(b, false)]
// Parse the 4707 out of "goroutine 4707 ["
b = bytes.TrimPrefix(b, goroutineSpace)
i := bytes.IndexByte(b, ' ')
if i < 0 {
panic(fmt.Sprintf("No space found in %q", b))
}
b = b[:i]
n, err := strconv.ParseUint(string(b), 10, 64)
if err != nil {
panic(fmt.Sprintf("Failed to parse goroutine ID out of %q: %v", b, err))
}
return n
}
// trace3/trace.go
func printTrace(id uint64, name, arrow string, indent int) {
indents := ""
for i := 0; i < indent; i++ {
indents += " "
}
fmt.Printf("g[%05d]:%s%s%s\n", id, indents, arrow, name)
}
var mu sync.Mutex
var m = make(map[uint64]int)
func Trace() func() {
pc, _, _, ok := runtime.Caller(1)
if !ok {
panic("not found caller")
}
fn := runtime.FuncForPC(pc)
name := fn.Name()
gid := curGoroutineID()
mu.Lock()
indents := m[gid] // 获取当前gid对应的缩进层次
m[gid] = indents + 1 // 缩进层次+1后存入map
mu.Unlock()
printTrace(gid, name, "->", indents+1)
return func() {
mu.Lock()
indents := m[gid] // 获取当前gid对应的缩进层次
m[gid] = indents - 1 // 缩进层次-1后存入map
mu.Unlock()
printTrace(gid, name, "<-", indents)
}
}
func A1() {
defer Trace()()
B1()
}
func B1() {
defer Trace()()
C1()
}
func C1() {
defer Trace()()
D()
}
func D() {
defer Trace()()
}
func A2() {
defer Trace()()
B2()
}
func B2() {
defer Trace()()
C2()
}
func C2() {
defer Trace()()
D()
}
func main() {
var wg sync.WaitGroup
wg.Add(1)
go func() {
A2()
wg.Done()
}()
A1()
wg.Wait()
}
输出结果如下:
g[00001]: ->main.A1
g[00001]: ->main.B1
g[00001]: ->main.C1
g[00001]: ->main.D
g[00001]: <-main.D
g[00001]: <-main.C1
g[00001]: <-main.B1
g[00001]: <-main.A1
g[00006]: ->main.A2
g[00006]: ->main.B2
g[00006]: ->main.C2
g[00006]: ->main.D
g[00006]: <-main.D
g[00006]: <-main.C2
g[00006]: <-main.B2
g[00006]: <-main.A2
每个人都有潜在的能量,只是很容易被习惯所掩盖,被时间所迷离,被惰性所消磨~