Golang性能分析(pprof)遇到问题求帮助

Golang性能分析(pprof)遇到问题求帮助

(pprof) list NewTokenPosition
Total: 39.22s
ROUTINE ======================== github.com/z7zmey/php-parser/parser.(*PositionBuilder).NewTokenPosition in /Users/z7zmey/work/go/src/github.com/z7zmey/php-parser/parser/position_builder.go
     3.66s      3.96s (flat, cum) 10.10% of Total
         .          .    104:	return pos
         .          .    105:}
         .          .    106:
         .          .    107:// NewTokenPosition returns new Position
         .          .    108:func (b *PositionBuilder) NewTokenPosition(t *scanner.Token) *position.Position {
         .      300ms    109:	pos := b.PositionPool.Get().(*position.Position)
     3.65s      3.65s    110:	pos.StartLine = t.Position.StartLine
         .          .    111:	pos.EndLine = t.Position.EndLine
         .          .    112:	pos.StartPos = t.Position.StartPos
         .          .    113:	pos.EndPos = t.Position.EndPos
         .          .    114:
      10ms       10ms    115:	return pos
         .          .    116:}

我无法理解为什么第110行花费了这么多时间。

重现步骤：

go get -u github.com/z7zmey/php-parser
cd $GOPATH/src/github.com/z7zmey/php-parser
make cpu_pprof

更多关于Golang性能分析(pprof)遇到问题求帮助的实战教程也可以访问 https://www.itying.com/category-94-b0.html

4 回复

（我运行了你的测试）

所以这里的背景是，这仅占整个基准测试运行时间30多秒中的约10%。我猜测你的位置构建器会对每个标记进行调用，而其余部分的开销不足以将这里的指针追踪和内存复制淹没到90%以上。

我预计这四行代码会被合并为一次复制操作，这就是性能分析器只将其视为第一行的原因。

更多关于Golang性能分析(pprof)遇到问题求帮助的实战系列教程也可以访问 https://www.itying.com/category-94-b0.html


如果我的理解正确，Go语言是在我们首次使用对象时分配内存，而不是在创建对象时分配。

我创建了 positionBuffer 切片，详见 @commit。之后，PositionPool 中的 New 函数耗时约 6.5 秒。这类似于 createToken 和 NewTokenPosition 这两个最频繁创建位置的函数耗时总和。

提交后，allocs/op 从 6281 减少到 4440，但 ns/op 略有增加。现在性能分析器显示时间主要消耗在切片扩容上。

我发现这种行为在分配新内存中有文档说明

new(T) 不会初始化内存，只会将其清零

上面的文章向我解释了为什么性能分析器显示如此奇怪的时间数据。

在 scanner/lexer.go:488 处，我们为 position.Position 创建了新的清零存储空间并返回其地址，这个过程很快。之后在 scanner/lexer.go:538 和 parser/position_builder.go:110 处，我们向清零对象赋值数据，Go 就开始进行内存初始化，这个过程很慢。

我尝试修改 scanner/lexer.go:488 来强制初始化内存，详见代码片段

func main() {
    fmt.Println("hello world")
}

从你的pprof输出可以看出，NewTokenPosition函数中第110行pos.StartLine = t.Position.StartLine消耗了3.65秒，这确实异常高。这种情况通常有以下几个原因：

可能的原因分析

  1. 结构体字段访问开销：如果t.Position或相关字段涉及复杂的内存访问或间接寻址
  2. 缓存未命中：频繁访问的结构体字段可能不在CPU缓存中
  3. 编译器优化问题：某些情况下编译器未能优化字段访问

优化建议

1. 使用局部变量缓存

func (b *PositionBuilder) NewTokenPosition(t *scanner.Token) *position.Position {
    pos := b.PositionPool.Get().(*position.Position)
    
    // 缓存token的position到局部变量
    tokenPos := t.Position
    pos.StartLine = tokenPos.StartLine
    pos.EndLine = tokenPos.EndLine
    pos.StartPos = tokenPos.StartPos
    pos.EndPos = tokenPos.EndPos
    
    return pos
}

2. 检查结构体对齐

确保相关结构体字段排列合理：

type Position struct {
    StartLine int
    EndLine   int
    StartPos  int
    EndPos    int
    // 确保字段按大小降序排列以减少填充
}

3. 批量处理优化

如果这是高频调用，考虑批量处理：

func (b *PositionBuilder) NewTokenPositions(tokens []*scanner.Token) []*position.Position {
    positions := make([]*position.Position, len(tokens))
    for i, t := range tokens {
        pos := b.PositionPool.Get().(*position.Position)
        tokenPos := t.Position
        pos.StartLine = tokenPos.StartLine
        pos.EndLine = tokenPos.EndLine
        pos.StartPos = tokenPos.StartPos
        pos.EndPos = tokenPos.EndPos
        positions[i] = pos
    }
    return positions
}

4. 深入分析具体原因

添加更细粒度的pprof分析：

import "runtime/pprof"

func (b *PositionBuilder) NewTokenPosition(t *scanner.Token) *position.Position {
    // 添加CPU分析标签
    labels := pprof.Labels("operation", "NewTokenPosition")
    pprof.Do(context.Background(), labels, func(ctx context.Context) {
        // 原有逻辑
    })
}

运行更详细的分析：

go test -cpuprofile=cpu.prof -bench=. -benchtime=10s
go tool pprof -list NewTokenPosition cpu.prof

建议先尝试第一种局部变量缓存的优化方法，这通常能解决大部分字段访问性能问题。

回到顶部