在验证 使用 Go 对接 iptables NFQUEUE 的例子 所使用的 go-nfqueue 第三方库 go-nfnetlink 的性能的时候，发现每秒只能处理 4 个网络包，遂使用 functrace 排查了起来。以下记录了排查过程。
排查过程
根据 functrace 的 REAME，对 go-nfqueue 例子代码添加了函数 trace 功能。但发现 functrace 打印的日志缺少时间记录，遂将 functrace 的 fmt.Printf 改为 log.Printf，并添加了时间戳：
1
2
3
|
func init() {
log.Default().SetFlags(log.Lmicroseconds | log.Ltime | log.Ldate) // 需要记录到微妙，函数执行耗时是微妙级别
}
|
最终发现了问题发生的函数（尴尬，问题现象没有复现出来）：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
|
// https://github.com/subgraph/go-nfnetlink/blob/master/nfnl_sock.go#L140
func (s *NetlinkSocket) readResponse(ch chan *netlinkResponse, msg *NfNlMessage) error {
defer functrace.Trace()()
select {
case resp := <-ch:
switch resp.rtype {
case responseAck:
return nil
case responseErr:
return syscall.Errno(resp.errno)
default:
return fmt.Errorf("unexpected response type: %v to message (seq=%d)", resp.rtype, msg.Seq)
}
case <-time.After(readResponseTimeout): // 如果内核没有响应 ack，则在这里超时 250 毫秒
s.removeResponseChannel(msg.Seq, true)
return fmt.Errorf("timeout waiting for expected response to message (seq=%d)", msg.Seq)
}
}
|
functrace 实现原理
functrace 的功能实现分为代码植入和日志打印两部分。bash -c "$(curl -fsSL https://raw.githubusercontent.com/bigwhite/functrace/main/scripts/batch_add_trace.sh)" 即是将当前目录下所有 Go 源代码文件里的函数都添加一行代码 defer functrace.Trace()()；这个 defer 实现了两次日志打印，第一次是打印了进入函数时的日志，第二次打印了退出函数时的日志。
trace 的功能实现
日志样例：
1
2
3
4
5
6
7
8
9
10
11
|
2021/12/14 14:32:49.684598 g[01]: ->github.com/subgraph/go-nfnetlink.(*NfNlMessage).Send
2021/12/14 14:32:49.684629 g[01]: ->github.com/subgraph/go-nfnetlink.(*NetlinkSocket).Send
2021/12/14 14:32:49.684921 g[01]: ->github.com/subgraph/go-nfnetlink.(*NetlinkSocket).sendWithAck
2021/12/14 14:32:49.686354 g[01]: ->github.com/subgraph/go-nfnetlink.(*NetlinkSocket).readResponse
2021/12/14 14:32:49.686255 g[19]: <-github.com/subgraph/go-nfnetlink.(*NetlinkSocket).fillRecvBuffer
...
2021/12/14 14:32:49.687066 g[19]: ->github.com/subgraph/go-nfnetlink.(*NetlinkSocket).fillRecvBuffer
2021/12/14 14:32:49.686978 g[01]: <-github.com/subgraph/go-nfnetlink.(*NetlinkSocket).readResponse
2021/12/14 14:32:49.687183 g[01]: <-github.com/subgraph/go-nfnetlink.(*NetlinkSocket).sendWithAck
2021/12/14 14:32:49.687203 g[01]: <-github.com/subgraph/go-nfnetlink.(*NetlinkSocket).Send
2021/12/14 14:32:49.687272 g[01]: <-github.com/subgraph/go-nfnetlink.(*NfNlMessage).Send
|
通过 goroutine ID 和日志补白分析可知一个函数的执行耗时是多久，比如函数 readResponse 耗时 624 微妙。
trace 的功能是找到当前 goroutine ID 和当前的函数名称，代码如下：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
|
var mu sync.Mutex // 保护下方的 m
var m = make(map[uint64]int) // goroutine id => 补白的 \t 数量
// 获取 goroutine ID，参考：https://github.com/cch123/goroutineid
func getGID() uint64 {
b := make([]byte, 64)
b = b[:runtime.Stack(b, false)]
b = bytes.TrimPrefix(b, []byte("goroutine "))
b = b[:bytes.IndexByte(b, ' ')]
n, _ := strconv.ParseUint(string(b), 10, 64)
return n
}
func printTrace(id uint64, name, typ string, indent int) {
indents := ""
for i := 0; i < indent; i++ {
indents += "\t"
}
log.Printf("g[%02d]:%s%s%s\n", id, indents, typ, name)
}
// 用法：在每个函数的第一行里添加 defer functrace.Trace()()
// defer 会先执行 Trace()，在函数退出时执行 Trace() 返回的函数。
func Trace() func() {
pc, _, _, ok := runtime.Caller(1)
if !ok {
panic("not found caller")
}
id := getGID()
fn := runtime.FuncForPC(pc) // 根据 pc 获取当前的函数名称
name := fn.Name()
mu.Lock()
v := m[id]
m[id] = v + 1
mu.Unlock()
printTrace(id, name, "->", v+1)
return func() {
mu.Lock()
v := m[id]
m[id] = v - 1
mu.Unlock()
printTrace(id, name, "<-", v)
}
}
|
代码植入
为每一个函数都人肉添加 defer functrace.Trace()() 是一件不现实的事。 functrace 作者已实现了一键为所有函数添加代码的工具。该工具利用 Go 内置的 go/ast, go/parser, go/token 这几个库，
- 将源代码解析成 ast
- 遍历 ast，判断是否是函数
- 如果是函数，插入代码
- 将修改后的代码写回原文件
源代码不长，直接阅读这段代码吧（functrace/pkg/generator/rewrite.Rewrite）。
总结
因为关注了 bigwhite 的公众号，所以当作者在公众号里提及 functrace 这个库时，就留意到了这个库的存在。终于有机会将 functrace 用起来了，物有所值。
