您现在的位置是：首页 > 其他

当前栏目

Go高性能系列教程之二：性能评估和分析

Go 教程性能程序高性能

2023-02-26 09:48:22 时间

在上一节基准测试中我们研究了对单个函数进行基准测试，这个的使用场景是在你已经提前知道瓶颈在哪里时很有用。

但是，通常你会发现我们并不知道性能瓶颈在哪里，你经常会问：

程序为什么耗时这么久，到底是哪里产生了性能瓶颈呢？

要回答上面的问题，我们就需要对整个程序进行概要分析以找出程序的瓶颈在哪里。

本节我们将使用Go的内置性能分析工具 pprof 对程序进行整体的性能分析。

—

pprof是什么

pprof 诞生自Google Perf Tools工具套件，并且已集成到Go运行时环境中。

pprof由两部分组成：

runtime/pprof 运行时包。用于采集程序数据样本。
go tool pprof工具。用于分析性能。

—

性能类型

pprof支持以下类型的性能分析：

CPU性能分析
内存性能分析
阻塞性能分析
互斥&竞争分析

2.1 CPU性能分析（CPU profiling）

CPU性能分析是运行时环境可通过一定的频率（默认是每10毫秒）中断一次并记录下当前运行协程的堆栈跟踪信息。它可确定应用程序在主动消耗 CPU 周期时花费时间的位置

一旦数据采集完成，我们就可以分析并找出执行耗时最长的代码路径。一个函数在性能分析中出现的次数越多，则其所在的代码路径花费的时间就越长。

2.2 内存数据采集（Memory profiling）

内存数据采集记录了堆内存分配的调用栈信息。栈内存分配的耗时可以忽略不计，所以不计入到内存性能分析中。

和CPU数据采集类似，内存数据采集默认是每分配1000次则采样一次。

由于内存数据采集是基于采样的，并且由于它跟踪的是未使用的分配，因此该技术很难确定应用程序的整体内存使用情况。

注意：因为是基于采样技术，所以内存分析并不能找到内存峰值。稍后我们将介绍一些较好的方式用来查看到应用程序整体使用内存情况。

2.3 阻塞性能分析（Blocking profiling）

阻塞分析是Go中独有的。它记录的是协程花在等待共享资源上的时间。阻塞分析可以显示出大量goroutine何时可以取得进展，但不阻塞了。

阻塞包括：

向一个非缓存的通道（unbuffered channel）上发送或接收数据
向一个已满的通道发送数据，或从一个空通道上接收数据
试图给一个互斥资源加锁，而该互斥资源已经被另一个协程占用。

一般我们会首先解决CPU、内存瓶颈之后，再来分析阻塞性能。

2.4 互斥分析

互斥分析主要关注在导致互斥锁争用导致延迟的操作上。

互斥分析不能提供给你该程序将要运行多长时间，以及已经运行了多长时间。相反，它能够记录该程序在等待互斥锁上花费了多长时间。

换句话说，就是如果互斥竞争被移除，那么会节省多少时间。

—

一次只做一类性能分析

开启采样并进行性能分析是有成本的。性能分析对程序是有一定的影响的，尤其是当你增加了内存分析采样频率的时候。

不要一次启用多个类型的性能分析。如果一次启用多个类型的性能分析，每个类型的只会关注自己的交互并且会丢掉其他的结果。

—

生成profiling

Go语言的运行时性能采集接口在runtime/pprof包下。runtime/pprof是比较低层的工具，并且由于历史原因，不同类型的性能概况收集接口也不统一。

正如我们上面看到的，pprof profiling是testing包中内置的，但如果我们想在testing.B中采集程序上下文的性能数据是非常困难的，所以必须直接使用runtime/pprof的API。

以下工具会使数据采集变得简单.

import "github.com/pkg/profile"

func main() {
  defer profile.Start().Stop()  
  //...
}

在上面这段代码中，我们使用了profile包。稍后我们将直接使用runtime/pprof接口。

—

分析profiling

到目前为止，我们已经知道pprof功能能够评估什么，并且如何产生profiling文件，接下来我们讨论使用pprof工具如何进行分析profiling。

通过以下命令分析profiling的内容：

go tool pprof /path/to/your/profile

该工具提供了分析数据的几种不同形式：文本、图表以及火焰图。

5.1 示例代码

我们通过一段统计单词的代码来做分析演示：

统计单词的代码：

package main

import (  
  "bufio"
  "fmt"
  "io"
  "log"
  "os"
  "unicode"
  "github.com/pkg/profile"
)

func readbyte(r io.Reader) (rune, error) {
  var buf [1]byte  

  _, err := r.Read(buf[:])
  return rune(buf[0]), err
}

func main() {  
  defer profile.Start(profile.CPUProfile, profile.ProfilePath(".")).Stop()    
  f, err := os.Open(os.Args[1])  
  if err != nil {
    log.Fatalf("could not open file %q:%v", os.Args[1], err)  
  }
  
  words := 0  
  inword := false  
  b := bufio.NewReader(f)  

  for {
    r, err := readbyte(b)    
    if err == io.EOF {      
      break
    }
    if err != nil {      
      log.Fatalf("could not read file %q:%v", os.Args[1], err)
    }    

    if unicode.IsSapce(r) && inword {
      words++ 
      inword = false
    }    

    inword = unicode.IsLetter(r)
  }
  fmt.Printf("%q:%d words\n", os.Args[1], words)}

让我们看看在moby.txt文件中有多少个单词：

% go build && time ./words moby.txt
"moby.txt": 181275 words
real    0m2.110
suser    0m1.264
ssys     0m0.944s

和unix的 wc -w命令比较一下：

% time wc -w moby.txt
215829 moby.txt
real    0m0.012
suser    0m0.009
ssys     0m0.002s

由此可知，统计的单词数量不一样。wc工具多出了19%，因为它对于一个单词的识别规则和我们程序是不一样的。这不重要--两个程序都将整个文件作为输入，并在一次过程中计算从单词到非单词的转换次数。

让我们研究一下为什么使用pprof工具的程序运行时间会有不同。

5.2 添加CPU测量分析

首先，编辑main.go文件并打开profiling

import (
  "github.com/pkg/profile"
)

func main() {
  defer profile.Start().Stop()
  // ...
}

现在当我们运行该程序的时候，一个cpu.pprof文件被创建。

% go run main.go moby.txt
2018/08/25 14:09:01 profile: cpu profiling enabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof
"moby.txt": 181275 words
2018/08/25 14:09:03 profile: cpu profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof

现在，我们得到了cpu.pprof文件，并且可以用go tool pprof命令进行分析

% go tool pprof /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof
Type: cpu
Time: Aug 25, 2018 at 2:09pm (AEST)
Duration: 2.05s, Total samples = 1.36s (66.29%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1.42s, 100% of 1.42s total
      flat  flat%   sum%        cum   cum%
     1.41s 99.30% 99.30%      1.41s 99.30%  syscall.Syscall
     0.01s   0.7%   100%      1.42s   100%  main.readbyte
         0     0%   100%      1.41s 99.30%  internal/poll.(*FD).Read
         0     0%   100%      1.42s   100%  main.main
         0     0%   100%      1.41s 99.30%  os.(*File).Read
         0     0%   100%      1.41s 99.30%  os.(*File).read
         0     0%   100%      1.42s   100%  runtime.main
         0     0%   100%      1.41s 99.30%  syscall.Read
         0     0%   100%      1.41s 99.30%  syscall.read

top 命令是最常用的一个命令。从上面的结果得知，99%的时间化在了syscall.Syscall函数上，只有一小部分时间花在了main.readbyte函数上。

我们还可以通过基于http服务器的pprof版本将profile中的数据直接图形化。

% go  tool pprof -http=:8080 /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof

该命令将打开一个web浏览器，并支持两种模式：

图形化模式
火焰图模式

在图形化模式下，最大的那个盒子花费的cpu时间越多 --- 我们看到 syscall.SysCall的花费时间占了整个程序的99.3%。盒子上指向syscall.Syscall的字符串代表直接调用者---如果多个代码路径都覆盖同一个函数，则可以有多个。箭头的大小代表在一个盒子的子容器中花费了多少时间，我们看到main.readbyte所花费的时间接近0秒。

后面我们会用专门文章来写如何读懂pprof的图形化报告。

5.4 改进我们的程序

我们程序慢的原因不是因为Go的syscall.Syscall慢。因为系统调用通常都是费时的操作。

根本原因是，每次对readbyte的调用都会导致一次缓冲区大小为1的syscall.Read操作。所以我们的程序执行syscall的数量等于输入的大小。在pprof图中我们可以看到，读取输入的内容占了主导地位。

看看如何改进我们的程序，如下：

func main() {
  defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
  // defer profile.Start(profile.MemProfile).Stop()
  f, err := os.Open(os.Args[1])
  if err != nil {
    log.Fatalf("could not open file %q: %v", os.Args[1], err)
  }
  
  b := bufio.NewReader(f)
  words := 0
  inword := false
  for {
    r, err := readbyte(b)
    if err == io.EOF {
      break
    }
    if err != nil {
      log.Fatalf("could not read file %q: %v", os.Args[1], err)
    }
    if unicode.IsSpace(r) && inword {
      words++
      inword = false
    }
    inword = unicode.IsLetter(r)
  }
  fmt.Printf("%q: %d words\n", os.Args[1], words)
}

通过在输入文件和readbyte之间插入一个bufio.Reader, 然后将该版本的花费时间和wc相比。他们是不是非常的接近了?

5.5 内存性能分析

新的 words分析中表明readbyte函数内部正在分配某些内容。我们可使用pprof进行研究：

defer profile.Start(profile.MemProfile).Stop()

然后运行该程序：

% go run main2.go moby.txt
2018/08/25 14:41:15 profile: memory profiling enabled (rate 4096), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof
"moby.txt": 181275 words
2018/08/25 14:41:15 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof

正如我们怀疑的是内存分配是从readbyte分配的---readbyte函数并不是那么复杂，只有三行：

func readbyte(r io.Reader) (rune, error) {
        var buf [1]byte 
        _, err := r.Read(buf[:])
        return rune(buf[0]), err
}

注：内存分配来自于 var buf [1]byte这一行代码。

5.6 分配对象 VS 重用对象

内存分析中有两个变体，在go tool pprof标志中通过参数命名可以体现。

-alloc_objects 报告在哪些地方分配了内存
-inuse_objects 当内存数据收集结束后，报告哪些地方还在使用内存

为了说明这一点，我们特意设计了这样一个程序，它将以受控方式分配一堆内存。

const count = 100000
var y []byte
func main() {
  defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
  y = allocate()
  runtime.GC()
}
// allocate allocates count byte slices and returns the first slice allocated.
func allocate() []byte {
  var x [][]byte
  for i := 0; i < count; i++ {
    x = append(x, makeByteSlice())
  }
  return x[0]
}
// makeByteSlice returns a byte slice of a random length in the range [0, 16384).
func makeByteSlice() []byte {
  return make([]byte, rand.Intn(2^14))
}

我们将内存监控的速率设置为1，即记录每次分配的堆栈跟踪。这会大大减慢该程序的速度，但是您很快就会知道原因。

% go run main.go
2018/08/25 15:22:05 profile: memory profiling enabled (rate 1), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof
2018/08/25 15:22:05 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof

让我们看下分配对象的图表，这是默认的，显示了在内存监控期间导致每个对象内存分配的调用过程。

% go tool pprof -http=:8080 /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof

超过99%的内存是在 makeByteSlice函数中分配的。接下来让我们使用-inuse_objects参数来看一下：

% go tool pprof -http=:8080 /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof

我们看到的不是在内存监控期间分配的对象，而是在获取监控时仍在使用的对象-这将忽略已由垃圾收集器回收的对象的堆栈跟踪。

5.7 阻塞测量

最后一个监控类型是阻塞监控。我们将使用net/http包下的 ClientServer的基准测试：

% go test -run=XXX -bench=ClientServer$ -blockprofile=/tmp/block.p net/http% go tool pprof -http=:8080 /tmp/block.

5.8 mutex profiling

互斥争用随着goroutine的数量而增加。

type AtomicVariable struct {
  mu  sync.Mutex
  val uint64
}

func (av *AtomicVariable) Inc() {
  av.mu.Lock()
  av.val++
  av.mu.Unlock()
}

func BenchmarkInc(b *testing.B) {
  var av AtomicVariable

  b.RunParallel(func(pb *testing.PB) {
    pb.ResetTimer()
    for pb.Next() {
      av.Inc()
    }
  })
}

按如下命令运行：

% go test -bench=. -cpu=1,2,4,8,16 ./examples/mutex

5.9 扩展阅读

Seven ways to profile a Go program：(https://talks.godoc.org/github.com/davecheney/presentations/seven.slide)(slides)

Seven ways to profile a Go program：https://www.youtube.com/watch?v=2h_NFBFrciI)(video 30mins)

Seven ways to profile a Go program：https://www.bigmarker.com/remote-meetup-go/Seven-ways-to-profile-a-Go-program(webcast, 60mins)

原文链接 <https://dave.cheney.net/high-performance-go-workshop/gophercon-2019.html#benchmarking>

猜你喜欢

基于AOP的动态数据源切换（附源码）
微服务7：通信之RPC
微服务6：通信之网关
架构与思维：高并发下解决主从延时的一些思路
微服务5：服务注册与发现（实践篇）
分布式：分布式系统下的唯一序列
微服务4：服务注册与发现
架构与思维：分布式锁方案分析
微服务3：微服务拆分策略
架构与思维：高并发下幂等性解决方案
微服务2：微服务全景架构
分布式：分布式事务（CAP、两阶段提交、三阶段提交）
微服务1：微服务及其演进史
架构与思维：一次缓存雪崩的灾难复盘
MySQL全面瓦解29：分库分表之Partition功能详解
MySQL全面瓦解28：分库分表
Java：导出Excel大批量数据的优化过程
MySQL全面瓦解27：主从复制（原理 + 实践）
MySQL全面瓦解26：代码评审中的MySQL（团队规范）
架构与思维：设计容量，到底有多重要？

zl程序教程

当前栏目

Go高性能系列教程之二：性能评估和分析

相关文章