Go 程序性能分析 101

时间  2020-01-27
标签 程序 性能 分析 栏目 系统性能 繁體版
原文   原文链接

过早优化是万恶之源。html

前言

本文来自 GopherCon 2019 的一个演讲，首先从一个计算文本字数的 go 程序与 wc 对比，经过 profile CPU 与内存逐步优化性能，涉及 Go 的并发模型及逃逸分析。而后由一个绘制曼德勃罗分形图的程序，讨论并发程序的执行追踪（trace）及并发程序能带来的性能提高的边界。git

pprof & trace

Go 内置的生态提供了大量的 API 及工具用于诊断程序的逻辑及性能问题。它们大体能够被分为如下几类：github

  • Profiling：Profiling 工具（如 pprof）用于分析程序中的复杂度与开销，如内存使用及函数调用频率等，并经过它们来标识程序中开销最大的部分。
  • Tracing：Tracing 用于分析某次调用或用户请求的整个流程中的延迟。其支持跨进程，并展现整个系统中每一个组件所花费的时间。
  • Debugging：Debugging 可以检验程序状态及执行流，可以暂停程序并检验其执行。
  • Runtime statistics and events：收集分析运行时统计及事件并提供程序健康情况的高级综述。尖峰/度的倾角可以帮助咱们肯定吞吐量，利用率和性能的变化。

更多关于 pprof 与 trace 的信息见：golang.org/doc/diagnos…golang

使用 pprof 分析 CPU 或内存使用

以下是一个文本字数计算程序，带着几分 Code smells，咱们将经过 pprof 逐步分析程序中到底有哪些问题。web

package main

import (
	"fmt"
	"io"
	"log"
	"os"
	"unicode"
)

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

func main() {
	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
	for {
		r, err := readbyte(f)
		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)
}
复制代码

这里咱们有一份用于测试程序的文本文件，1.2 M 大小。数组

$ ls -lh moby.txt
-rw-r--r--  1 f1renze  staff   1.2M Jan 19 16:32 moby.txt
复制代码

咱们跑一下程序看看，读取 + 单词计数一共花了 2 秒钟，这好像不太行。缓存

$ time go run main.go moby.txt
"moby.txt": 181275 words
        2.13 real         1.41 user         1.81 sys
复制代码

咱们先 profile 一下 CPU，以下在代码中加上生成 profile 文件的代码段：bash

func main() {
  # 添加如下代码
	cpuProfile, _ := os.Create("cpu_profile")
	pprof.StartCPUProfile(cpuProfile)
	defer pprof.StopCPUProfile()
	
	....
复制代码

从新执行程序而后以 web 形式启动 pprof（须要先安装 Graphviz）：并发

go tool pprof -http=:8081 cpu_profile
复制代码

默认界面就是一个详细的函数调用关系、耗时图。这里主要有三个分支。svg

image.png

先来看最右边，syscall.syscall 共占用 cpu 0.93s，为啥在 syscall 上花了这么多时间嘞？咱们带着问题看一下原始代码，看到在 for 循环中程序不断调用 readbyte 方法读取文件：

...
for {
		r, err := readbyte(f)
		if err == io.EOF {
			break
		}
...
复制代码

而在此方法中，每次都只读取一个字节：

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

问题就出在这！

truth.jpg

正是未缓冲的频繁读取致使了长时间的 syscall 占用，这还会致使另一个问题，看调用栈的左边，runtime.pthread_cond_signal 与 runtime.pthread_cond_wait 分别花费了 0.58s 与 1s。

因为 go 的协程由内置的调度器进行调度，即 GMP 模型，每一个 P 分配一个 M （实际 OS 线程）执行 G，当执行 G 的 M 陷入同步阻塞系统调用（如 文件 IO）时，P 会被转移到新的 M （新建的 OS 线程或线程缓存）上。以下图：

img1

M1 执行 G 时陷入系统调用，调度器将 M1 与 P 分离（G1 仍与 M1 链接），并为 P 分配 M2 ，而后从 P 的 Local Run Queue 选择 G2 执行（此时在 M2 上进行上下文切换）。

img2

当 G1 发起的同步阻塞调用执行完时，G1 会被移回 P 的 Local Run Queue 。而 M1 加入线程缓存中。

img3

因此真正的缘由是：屡次系统调用带来的开销，加上陷入系统调用的 M 致使 P 的转移，使得程序性能很是差。

查明缘由后咱们优化一下代码：

words := 0
inword := false
# 返回带缓冲的 io.Reader
b := bufio.NewReader(f)
for {
  # 由 buffer 中读取
  r, err := readbyte(b)
  if err == io.EOF {
    break
  }
复制代码

查看运行时间，仅为以前的执行时间的零头：

$ time go run main.go moby.txt
"moby.txt": 181275 words
        0.63 real         0.29 user         0.25 sys
复制代码

再次查看 CPU profile ，发现只剩下一个分支了，由于程序中只有一次系统调用，耗时几乎能够忽略不计：

image.png

显然针对 CPU 的 profile 不能提供给咱们更多信息了，接下来咱们 profile 一下程序内存使用。

为了演示此处将采样率修改成 1，profiler 会收集所有内存分配信息。（通常不推荐这么作，由于这会拖慢程序运行效率）

func main() {
# 将以前 profile CPU 的代码注释掉后添加如下代码
memProfile, _ := os.Create("mem_profile")
runtime.MemProfileRate = 1

defer func() {
  pprof.WriteHeapProfile(memProfile)
  memProfile.Close()
}()
...
复制代码

查看调用栈及内存分配展现

image.png

能够看到 main.readbyte 分配了 1.2 m 的内存，与 moby.txt 文件大小相同，点击 source 查看内存分配具体位置：

image.png

对比一下 main 函数与 readbyte 函数，能够看到 bufio 返回的 reader 仅占 4kb 内存而 readbyte 中的 buf 数组却分配了 1.2 mb 的内存！

image.png
image.png

因为 buf 这个数组在函数中声明，理论上应该被分配函数栈空间上，随着函数返回直接释放。然而 profile 结果彷佛不是这样，咱们来看下编译器的逃逸分析日志：

$ go build -gcflags=-m main.go
# command-line-arguments
...
./main.go:15:6: moved to heap: buf
./main.go:43:21: moved to heap: buf
....
复制代码

省略无关信息，此处能够看到编译器将本是函数中局部变量的 buf 分配到堆上。因为变量被分配到堆或栈上是由 go 编译器决定的，每次进入 readbyte 函数时声明的 buf 都被分配到堆上，加起来的内存大小即为文件自己的大小。

咱们将 buf 改成全局变量再次 profile，问题解决：

image.png

使用 Trace 分析 Groutine 执行过程

pprof 足够强大，但一般 Go 程序中包含了大量的并发操做，此时 profile CPU 或内存或许已经不能提供更多有用的信息。而官方提供了超级好用的 trace 帮助咱们进一步分析高并发程序的性能。

这是一个支持多种工做模式的绘制曼德勃罗分形图（Mandelbrot set）的程序，其主要工做是根据每一个像素的坐标计算出值并填充颜色，无需了解具体细节由于本文的重点是 trace：

// mandelbrot example code adapted from Francesc Campoy's mandelbrot package.
// https://github.com/campoy/mandelbrot
package main

import (
	"flag"
	"image"
	"image/color"
	"image/png"
	"log"
	"os"
	"sync"
)

func main() {
	var (
		height  = flag.Int("h", 1024, "height of the output image in pixels")
		width   = flag.Int("w", 1024, "width of the output image in pixels")
		mode    = flag.String("mode", "seq", "mode: seq, px, row, workers")
		workers = flag.Int("workers", 1, "number of workers to use")
	)
	flag.Parse()

	const output = "mandelbrot.png"

	// open a new file
	f, err := os.Create(output)
	if err != nil {
		log.Fatal(err)
	}

	// create the image
	c := make([][]color.RGBA, *height)
	for i := range c {
		c[i] = make([]color.RGBA, *width)
	}

	img := &img{
		h: *height,
		w: *width,
		m: c,
	}

	switch *mode {
	case "seq":
		seqFillImg(img)
	case "px":
		oneToOneFillImg(img)
	case "row":
		onePerRowFillImg(img)
	case "workers":
		nWorkersPerRowFillImg(img, *workers)
	default:
		panic("unknown mode")
	}

	// and encoding it
	if err := png.Encode(f, img); err != nil {
		log.Fatal(err)
	}
}

type img struct {
	h, w int
	m    [][]color.RGBA
}

func (m *img) At(x, y int) color.Color { return m.m[x][y] }
func (m *img) ColorModel() color.Model { return color.RGBAModel }
func (m *img) Bounds() image.Rectangle { return image.Rect(0, 0, m.h, m.w) }

// SEQSTART OMIT
func seqFillImg(m *img) {
	for i, row := range m.m {
		for j := range row {
			fillPixel(m, i, j)
		}
	}
}

// SEQEND OMIT

func oneToOneFillImg(m *img) {
	var wg sync.WaitGroup
	wg.Add(m.h * m.w)
	for i, row := range m.m {
		for j := range row {
			go func(i, j int) {
				fillPixel(m, i, j)
				wg.Done()
			}(i, j)
		}
	}
	wg.Wait()
}

func onePerRowFillImg(m *img) {
	var wg sync.WaitGroup
	wg.Add(m.h)
	for i := range m.m {
		go func(i int) {
			for j := range m.m[i] {
				fillPixel(m, i, j)
			}
			wg.Done()
		}(i)
	}
	wg.Wait()
}

func nWorkersFillImg(m *img, workers int) {
	c := make(chan struct{ i, j int })
	for i := 0; i < workers; i++ {
		go func() {
			for t := range c {
				fillPixel(m, t.i, t.j)
			}
		}()
	}

	for i, row := range m.m {
		for j := range row {
			c <- struct{ i, j int }{i, j}
		}
	}
	close(c)
}

func nWorkersPerRowFillImg(m *img, workers int) {
	c := make(chan int, m.h)
	var wg sync.WaitGroup
	wg.Add(workers)
	for i := 0; i < workers; i++ {
		go func() {
			for row := range c {
				for col := range m.m[row] {
					fillPixel(m, row, col)
				}
			}
			wg.Done()
		}()
	}

	for row := range m.m {
		c <- row
	}
	close(c)
	wg.Wait()
}

func fillPixel(m *img, x, y int) {
	const n = 1000
	const Limit = 2.0
	Zr, Zi, Tr, Ti := 0.0, 0.0, 0.0, 0.0
	Cr := (2*float64(x)/float64(n) - 1.5)
	Ci := (2*float64(y)/float64(n) - 1.0)

	for i := 0; i < n && (Tr+Ti <= Limit*Limit); i++ {
		Zi = 2*Zr*Zi + Ci
		Zr = Tr - Ti + Cr
		Tr = Zr * Zr
		Ti = Zi * Zi
	}
	paint(&m.m[x][y], Tr, Ti)
}

func paint(c *color.RGBA, x, y float64) {
	n := byte(x * y * 2)
	c.R, c.G, c.B, c.A = n, n, n, 255
}
复制代码

咱们跑一下看看，有点慢：

$ time go run mandelbrot.go 
        1.93 real         1.70 user         0.27 sys
复制代码

因为默认工做模式是顺序执行计算，程序自己除了建立文件及图片编码操做也没有其余额外的 IO 操做，代码上进一步优化的空间有限。这里咱们直接使用 trace 看一下分析结果，首先加入生成 trace 代码段：

func main() {
	var (
		height  = flag.Int("h", 1024, "height of the output image in pixels")
		width   = flag.Int("w", 1024, "width of the output image in pixels")
		mode    = flag.String("mode", "seq", "mode: seq, px, row, workers")
		workers = flag.Int("workers", 1, "number of workers to use")
	)
	flag.Parse()
	
	# 加入如下代码段
	var fn string
	switch *mode {
	case "seq":
		fn = "trace.seq"
	case "px":
		fn = "trace.px"
	case "row":
		fn = "trace.row"
	case "workers":
		fn = "trace.workers"
	}
	traceFile, _ := os.Create(fn)
	if err := trace.Start(traceFile); err != nil {
		log.Fatal(err)
	}
	defer trace.Stop()
	
	....
复制代码

运行程序后使用 go tool trace trace.seq 在 Chrome 中查看：

image.png

image.png

Tips: Shift + ? 查看命令帮助，w/s 放大 / 缩小

细心的同窗可能会发现，只有 Proc 0 一直在工做，其余几乎都处于闲置状态，因为不一样像素的计算任务彼此独立，据此能够将计算任务交由不一样的 Goroutine 来完成。

既然如此，咱们换个工做模式，直接并行化计算每一个像素，程序中已经给出了实现：

func oneToOneFillImg(m *img) {
	var wg sync.WaitGroup
	wg.Add(m.h * m.w)
	for i, row := range m.m {
		for j := range row {
			go func(i, j int) {
				fillPixel(m, i, j)
				wg.Done()
			}(i, j)
		}
	}
	wg.Wait()
}
复制代码

咱们切换到对应的 px 工做模式看看：

$ time go run mandelbrot.go -mode px
        2.01 real         7.26 user         2.90 sys
复制代码

好吧，很是奇怪的是程序竟然更慢了，咱们使用 go tool trace trace.seq 看一下到底是怎么一回事。

生成的 trace 文件大小取决于 Goroutine 数量，运行这条命令会比较慢

image.png

因为 Goroutine 数量过多，能够看到 trace 文件被分为许多片断，查看其中一个片断：

image.png

这回没有空闲的 Proc 了，但执行流彷佛断断续续的，放大后看很是明显：

image.png

因此问题就出在这，并发粒度过小了，每一个 Goroutine 的工做量过小，甚至抵不上启动及调度的开销。天下没有免费的午饭，过多的 Groutine 也会带来额外的负担。

接下来咱们调整一下并发粒度，将每一行的计算任务分配到不一样的 Goroutine 上，对应的模式及源码以下：

time go run mandelbrot.go -mode row
        0.85 real         1.85 user         0.32 sys
复制代码
func onePerRowFillImg(m *img) {
	var wg sync.WaitGroup
	wg.Add(m.h)
	for i := range m.m {
		go func(i int) {
			for j := range m.m[i] {
				fillPixel(m, i, j)
			}
			wg.Done()
		}(i)
	}
	wg.Wait()
}
复制代码

能够看到明显比以前两个模式要快上许多，看下 trace 如何：

image.png

像素计算部分执行流看起来极度温馨，而且充分利用了 CPU 资源，12 个线程所有跑满（超线程的 6 核 CPU）。放大后能够看到 Goroutine 之间几乎没有空隙，不由赞叹 Go 才是世界上最好的语言😆。

image.png

固然，这种模式依然有其缺点，注意到 trace 界面最上方 Groutine 一栏中有一个明显的波动，尽管咱们调整了并发粒度其依然会在短期内产生大量 Goroutine 而后依次执行它们。实际上因为 CPU 核数是固定的，同一时间并行执行 Goroutine 的 OS 线程数也是固定的，由此咱们能够将 Goroutine 池化复用，节省资源，其一般被称为 Worker Pool。

Worker Pool 有很是多种实现，可是却大同小异，首先启动必定的 Goroutine 做为 Worker，而后 Worker 经过 Channel 消费须要执行的 Task。程序中给出了一个简单实现以下：

func nWorkersPerRowFillImg(m *img, workers int) {
	c := make(chan int, m.h)
	var wg sync.WaitGroup
	wg.Add(workers)
	for i := 0; i < workers; i++ {
		go func() {
			for row := range c {
				for col := range m.m[row] {
					fillPixel(m, row, col)
				}
			}
			wg.Done()
		}()
	}

	for row := range m.m {
		c <- row
	}
	close(c)
	wg.Wait()
}
复制代码

咱们看一下执行时间，比 row 模式要快一些。这里要注意的是须要手动指定 Worker 的数量，等同于当前硬件最大支持的线程数，能够在 Go 中使用 fmt.Println(runtime.NumCPU()) 查看。

time go run mandelbrot.go -mode workers -workers 12
        0.74 real         1.86 user         0.26 sys
复制代码

查看 trace 能够看到计算阶段始终保持着等同于 Worker 数量的 Groutine 在运行

image.png

Worker Pool 很是好用但也不是银弹，不一样方案适用于不一样场景，此处不过多讨论。回到当前程序自己，这几种方案最终加速的都是计算任务部分，要想加速图像编码部分难度无疑会提高几个档次。

Amdahl's law

law.svg

而并行化可以带来的加速也不是无限的。如上图，阿姆达尔定律（Amdahl's law）表示了并行处理器数量与效率提高的关系，加速程序的关键取决于其中必须串行执行的部分（好比 mandelbrot 这个程序最快时也须要花费约 50% 的时间用于编码图片）。当程序中 95% 的执行均可以并行化时，即便将 CPU 数量提高到数千个，加速效率也只能限制在 20 倍。

总结

这真的是一个很是棒的演讲，深刻浅出地讲述了 Go 性能分析的三种方式，其中还涉及了许多底层的知识点。以为意犹未尽的朋友能够看看做者的相关文章 👉 dave.cheney.net/high-perfor…

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程