GO的花式调优技术

内存管理

在开始探索 Go 调优技术和工具之前,我们需要先了解一下 Go 内存模型,它可以帮助我们理解内存是如何使用的。

Go 实现的是并行的标记-清除垃圾回收器。在传统的标记-清除模型中,垃圾回收器会先让程序停下来(也就是,stop the world),然后查找已经失效的对象,并把这些对象清理掉(也就是,释放内存)。因为程序在运行中会移动引用(references),导致垃圾的识别和清理出现困难。同时,垃圾回收也会导致延迟和其他的问题。在 Go 语言中GC 是并发执行的,所以 GC 执行时,用户可能不会注意到暂停或者延迟。

调优方式

要监控程序性能,有下面几种方式:

  • Timers: 计时器,用于基准测试,比较程序修改前修改后的差异。
  • Profilers: 专业的调优工具,用于更高级的程序验证。

工具矩阵

优点缺点ReadMemStats- 简单、快速、易用。

– 仅描述内存使用情况。- 需要改代码。pprof- 详述CPU和内存使用情况。

– 可以远程分析。

– 可以生成图像。- 需要改代码。

– 需调用API。trace- 帮助分析过程数据。

– 强大的调试界面。

– 易实现问题区域的可视化。- 需要改代码。

– UI界面复杂。

– 理解需要一点时间。

分析步骤

无论你用哪一种分析工具,有一个通用的原则:

  1. 识别更高层面的瓶颈
  • 例如,你可能发现了一个长时间运行的函数。
  1. 减少操作量
  • 找出可替换的方法,减少时间消耗, 或者调用次数。
  • 找出可替换的方法,减少内存分配量。
  1. 向下挖掘数据
  • 使用工具,找出更低层、更细节的数据。

思考性能更好的算法或者数据结构;找到更简单的处理方式;从实效角度审视你的代码。

基本用例

我们看一段简单的程序,它是用 Go 1.9.2 编写的:

package main

import (
    "log"
)

// bigBytes 函数分配了大约 100 MB 内存
func bigBytes() *[]byte {
    s := make([]byte, 100000000)
    return &s
}

func main() {
    for i := 0; i < 10; i++ {
        s := bigBytes()
        if s == nil {
            log.Println("oh noes")
        }
    }
}

执行这个程序大概用了 0.2s。

这个程序运行的不算慢,我们仅仅用它来衡量内存使用情况。

ReadMemStats

关于内存分配的情况,最简单的方式是利用 runtime 包的 MemStats。

在下面的代码片段中,我们调整了 main 函数,打印出详细的内存统计信息。

func main() {
    var mem runtime.MemStats

    fmt.Println("memory baseline...")

    runtime.ReadMemStats(&mem)
    log.Println(mem.Alloc)
    log.Println(mem.TotalAlloc)
    log.Println(mem.HeapAlloc)
    log.Println(mem.HeapSys)

    for i := 0; i < 10; i++ {
        s := bigBytes()
        if s == nil {
            log.Println("oh noes")
        }
    }

    fmt.Println("memory comparison...")

    runtime.ReadMemStats(&mem)
    log.Println(mem.Alloc)
    log.Println(mem.TotalAlloc)
    log.Println(mem.HeapAlloc)
    log.Println(mem.HeapSys)
}

运行程序,可以看到下面的结果:

memory baseline…

2017/10/29 08:51:56 56480
2017/10/29 08:51:56 56480
2017/10/29 08:51:56 56480
2017/10/29 08:51:56 786432

memory comparison...

2017/10/29 08:51:56 200074312
2017/10/29 08:51:56 1000144520
2017/10/29 08:51:56 200074312
2017/10/29 08:51:56 200704000

这样我们可以看到,程序在启动时和在结束时(也就是通过bigBytes函数分配了大量内存后),内存分配上的差异。TotalAllocHeapAlloc是我们最关心的两项。

总体内存分配(total allocations)指的是累计的内存分配总量(这个值在内存释放后不会变小)。堆内存分配(heap allocations)指的是在观测时,实时的内存分配情况,包括可达和不可达的对象(例如,垃圾回收器还没有释放的对象)。要意识到,观测后实际在用内存(in use)可能会更少。

更多信息可参考MemStats docs,(包含Mallocs或者Frees)。

Pprof

Pprof是一款可视化的性能分析工具。用于确定应用程序运行过程中的 CPU 和内存使用情况。

可以通过下面的方式安装:

go get github.com/google/pprof

我们先理解性能概要(profile)的定义:

性能概要(profile)是由多个堆栈跟踪组成的。堆栈跟踪能提供特殊事件(比如,内存分配)的调用顺序。包(Packages)可以创建、维护各自的性能概要信息。最常见的用途就是追踪资源的使用,而这些资源使用后必须被明确的关闭(closed),比如文件的操作、网络连接的关闭。–pkg/runtime/pprof

使用这个工具,有下面几种方式:

  1. 开发时在程序中加入指令代码,生成分析用的.profile文件。
  2. 通过 web server 远程分析程序(不明确生产.profile文件)。
注意: 性能概要文件不一定带有.profile后缀名 (文件类型可以自己定义)

在开发时生成 .profile

在这一段,我们研究一下性能分析,涵盖 CPU 和内存的分配情况。从 CPU 性能分析开始。

CPU 分析

在下面的例子中,我们导入了"runtime/pprof"包,并增加了相关的 API 调用,目的是记录 CPU 的数据:

package main

import (
    "log"
    "os"
    "runtime/pprof"
)

// bigBytes 函数每次分配 100 MB 内存
func bigBytes() *[]byte {
    s := make([]byte, 100000000)
    return &s
}

func main() {
    pprof.StartCPUProfile(os.Stdout)
    defer pprof.StopCPUProfile()

    for i := 0; i < 10; i++ {
        s := bigBytes()
        if s == nil {
            log.Println("oh noes")
        }
    }
}
注意:为了简单明了,我们使用了os.Stdout(不在程序中创建文件)而是利用 shell 重定向输出,用于创建性能概要文件。

然后编译、运行,将性能数据保存到文件:

go build -o app && time ./app > cpu.profile

最后,使用 go tool 命令,以交互的方式检查数据:

go tool pprof cpu.profile

可以看到交互提示符 (pprof),执行top命令,输出如下信息:

(pprof) top
Showing nodes accounting for 180ms, 100% of 180ms total
    flat  flat%   sum%        cum   cum%
    180ms   100%   100%      180ms   100%  runtime.memclrNoHeapPointers /.../src/runtime/memclr_amd64.s
        0     0%   100%      180ms   100%  main.bigBytes /.../code/go/profiling/main.go (inline)
        0     0%   100%      180ms   100%  main.main /.../code/go/profiling/main.go
        0     0%   100%      180ms   100%  runtime.(*mheap).alloc /.../src/runtime/mheap.go
        0     0%   100%      180ms   100%  runtime.largeAlloc /.../src/runtime/malloc.go
        0     0%   100%      180ms   100%  runtime.main /.../src/runtime/proc.go
        0     0%   100%      180ms   100%  runtime.makeslice /.../src/runtime/slice.go
        0     0%   100%      180ms   100%  runtime.mallocgc /.../src/runtime/malloc.go
        0     0%   100%      180ms   100%  runtime.mallocgc.func1 /.../src/runtime/malloc.go
        0     0%   100%      180ms   100%  runtime.systemstack /.../src/runtime/asm_amd64.s

这表示runtime.memclrNoHeapPointers占用了最多的CPU时间。

我们一行一行的分解程序,可以更准确地观察 CPU 的使用情况。

使用list 命令,通过main.main可以看到主函数 main 。

让我们列出main名称空间下的所有函数:

(pprof) list main.
Total: 180ms
ROUTINE ======================== main.bigBytes in /.../go/profiling/main.go
            0      180ms (flat, cum)   100% of Total
            .          .      6:   "runtime/pprof"
            .          .      7:)
            .          .      8:
            .          .      9:// bigBytes allocates 10 sets of 100 megabytes
            .          .     10:func bigBytes() *[]byte {
            .      180ms     11:   s := make([]byte, 100000000)
            .          .     12:   return &s
            .          .     13:}
            .          .     14:
            .          .     15:func main() {
            .          .     16:   pprof.StartCPUProfile(os.Stdout)
ROUTINE ======================== main.main in /.../code/go/profiling/main.go
            0      180ms (flat, cum)   100% of Total
            .          .     15:func main() {
            .          .     16:   pprof.StartCPUProfile(os.Stdout)
            .          .     17:   defer pprof.StopCPUProfile()
            .          .     18:
            .          .     19:   for i := 0; i < 10; i++ {
            .      180ms     20:           s := bigBytes()
            .          .     21:           if s == nil {
            .          .     22:                   log.Println("oh noes")
            .          .     23:           }
            .          .     24:   }
            .          .     25:}

好了,我们可以看到 180ms 都花费在bigBytes函数。在bigBytes函数中,绝大部分时间花费在分配内存命令上make([]byte, 100000000)

内存分析

在进入后面的主题前,我们看一下如何收集内存使用信息。

我们要稍微调整一下程序,把StartCPUProfile替换为WriteHeapProfile(并把这个调用移到main函数的底部,如果在main函数的顶部调用,内存分配还没有开始),并且删掉StopCPUProfile调用。(通过快照的方式记录堆的使用情况,而不是像 CPU 性能分析那样,是一个持续运行的过程):

package main

import (
    "log"
    "os"
    "runtime/pprof"
)

// bigBytes allocates 10 sets of 100 megabytes
func bigBytes() *[]byte {
    s := make([]byte, 100000000)
    return &s
}

func main() {
    for i := 0; i < 10; i++ {
        s := bigBytes()
        if s == nil {
            log.Println("oh noes")
        }
    }

    pprof.WriteHeapProfile(os.Stdout)
}

再一次,我们编译、执行程序,并重定向 stdout 到文件(为简单起见),如果你愿意,也可以在程序中动态创建一个文件:

go build -o app && time ./app > memory.profile

现在我们就可以运行 pprof ,以交互的方式查看内存分析数据:

go tool pprof memory.profile

运行 top 命令,可以看到下面的输出:

(pprof) top
Showing nodes accounting for 95.38MB, 100% of 95.38MB total
        flat  flat%   sum%        cum   cum%
    95.38MB   100%   100%    95.38MB   100%  main.bigBytes /...ain.go (inline)
            0     0%   100%    95.38MB   100%  main.main /.../profiling/main.go
            0     0%   100%    95.38MB   100%  runtime.main /.../runtime/proc.go

因为是个简单的示例程序,可以很清晰地看出主要的内存分配发生在main.bigBytes函数中。

如果想看一些更详细的数据,可以执行list main.

(pprof) list main.
Total: 95.38MB
ROUTINE ======================== main.bigBytes in /.../go/profiling/main.go
    95.38MB    95.38MB (flat, cum)   100% of Total
            .          .      6:   "runtime/pprof"
            .          .      7:)
            .          .      8:
            .          .      9:// bigBytes allocates 10 sets of 100 megabytes
            .          .     10:func bigBytes() *[]byte {
    95.38MB    95.38MB     11:   s := make([]byte, 100000000)
            .          .     12:   return &s
            .          .     13:}
            .          .     14:
            .          .     15:func main() {
            .          .     16:   for i := 0; i < 10; i++ {
ROUTINE ======================== main.main in /.../code/go/profiling/main.go
            0    95.38MB (flat, cum)   100% of Total
            .          .     12:   return &s
            .          .     13:}
            .          .     14:
            .          .     15:func main() {
            .          .     16:   for i := 0; i < 10; i++ {
            .    95.38MB     17:           s := bigBytes()
            .          .     18:           if s == nil {
            .          .     19:                   log.Println("oh noes")
            .          .     20:           }
            .          .     21:   }
            .          .     22:

逐行指出内存的分配情况。

通过 Web 服务器远程分析

在下面的例子中修改了代码,我们建立了一个 Web 服务,并导入"net/http/pprof"包 (https://golang.org/pkg/net/http/pprof/),以实现自动分析。

注意:如果你的程序已经使用了 Web 服务器,你不必再新建一个。pprof 包会挂载到 web 服务的多路复用器(multiplexer)。
package main

import (
    "fmt"
    "log"
    "net/http"
    _ "net/http/pprof"
    "sync"
)

// bigBytes allocates 10 sets of 100 megabytes
func bigBytes() *[]byte {
    s := make([]byte, 100000000)
    return &s
}

func main() {
    var wg sync.WaitGroup

    go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()

    for i := 0; i < 10; i++ {
        s := bigBytes()
        if s == nil {
            log.Println("oh noes")
        }
    }

    wg.Add(1)
    wg.Wait() // 为了 pprof 分析的正常运行,阻止 `main` 函数退出
}

编译、运行这个程序,通过路径/debug/pprof/可以访问性能分析数据,完整路径:

http://localhost:6060/debug/pprof/

你应该可以看到类似下面的内容:

profiles:
0	block
4	goroutine
5	heap
0	mutex
7	threadcreate

full goroutine stack dump

/debug/pprof/

这里的 block,goroutine,heap,mutex,threadcreate 都链接到相应的数据,这些链接对应不同的.profile文件。处理.profile文件还需要其他工具。

首先,先认识一下这五个分析文件的含义:

  • block: 同步原语引起阻塞的跟踪信息;
  • goroutine: 所有当前 go 协程的跟踪信息;
  • heap: 堆内存分配情况;
  • mutex: 竞争互斥的跟踪信息;
  • threadcreate: 创建操作系统线程的跟踪信息;

web 服务器也可以产生 30s 的 CPU 性能分析文件,访问地址http://localhost:6060/debug/pprof/profile(这个文件不能在浏览器中展示,但可以下载到你的本地系统中)

在访问/debug/pprof/时,看不到 CPU 性能分析的链接。因为做 CPU 性能分析需要调用特殊的 API(也就是,StartCPUProfileStopCPUProfile函数),只有调用后才产生输出流,最终下载到你的文件系统。

web 服务器可以产生追踪文件,访问地址http://localhost:6060/debug/pprof/trace?seconds=5(与 CPU 性能分析一样的原因,都没有列出来,调用后才产生输出数据,然后下载到你的文件系统)。这个追踪文件需要用 go tool trace 进行解析(后面的章节会讲解 go tool trace )。

注意:pprof 的选项信息可以参考:golang.org/pkg/net/http/pprof/

如果使用了定制的 URL 路由,你需要注册单独的pprof端点(endpoint):

package main

import (
    "net/http"
    "net/http/pprof"
)

func message(w http.ResponseWriter, r *http.Request) {
    w.Write([]byte("Hello World"))
}

func main() {
    r := http.NewServeMux()
    r.HandleFunc("/", message)

    r.HandleFunc("/debug/pprof/", pprof.Index)
    r.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
    r.HandleFunc("/debug/pprof/profile", pprof.Profile)
    r.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
    r.HandleFunc("/debug/pprof/trace", pprof.Trace)

    http.ListenAndServe(":8080", r)
}

理论上,你需要在命令行使用go tool pprof。这样以交互的方式,更容易解释和查询数据。

为了这样做,先要运行二进制文件,然后在 shell 中执行:

go tool pprof http://localhost:6060/debug/pprof/<.profile>

例如,我们要看一下堆内存分析数据:

go tool pprof http://localhost:6060/debug/pprof/heap

在这你可以看到交互提示符:

Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in /.../pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: inuse_space
Time: Oct 27, 2017 at 10:01am (BST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
注意:type 设定为inuse_space(表示在用的内存数量)

你可以输入help或者o查看可用的操作,如上所示。

这里是一些有用的命令:

  • top: 以文本形式输出最前面的记录
  • topK: K 代表具体数字 (例如, top2 显示前两条记录)
  • list : 以文本形式输出记录

例如,执行top后,可以看到下面的输出:

Showing nodes accounting for 95.38MB, 100% of 95.38MB total
        flat  flat%   sum%        cum   cum%
    95.38MB   100%   100%    95.38MB   100%  main.bigBytes /...ain.go (inline)
            0     0%   100%    95.38MB   100%  main.main /.../profiling/main.go
            0     0%   100%    95.38MB   100%  runtime.main /.../runtime/proc.go

对于一个简单的应用程序,可以很好指出哪个函数最耗内存(在本例中,main.bigBytes函数分配内存最多)

如果做更精确的分析,可以用list main.main

Total: 95.38MB
ROUTINE ======================== main.main in /.../profiling/main.go
    95.38MB    95.38MB (flat, cum)   100% of Total
            .          .      8:   "sync"
            .          .      9:)
            .          .     10:
            .          .     11:// bigBytes allocates 10 sets of 100 megabytes
            .          .     12:func bigBytes() *[]byte {
    95.38MB    95.38MB     13:   s := make([]byte, 100000000)
            .          .     14:   return &s
            .          .     15:}
            .          .     16:
            .          .     17:func main() {
            .          .     18:   fmt.Println("starting...")

这样可以逐行指出内存使用情况。

前面有提到,堆内存分析的默认类型是在用内存。还有一种类型,表示程序在整个生命周期分配的内存总量,可以使用-alloc_space标识切换到这种模式:

go tool pprof -alloc_space http://localhost:6060/debug/pprof/heap

执行list命令,我们看一下区别:

(pprof) list main.bigBytes

Total: 954.63MB
ROUTINE ======================== main.bigBytes in /.../go/profiling/main.go
    953.75MB   953.75MB (flat, cum) 99.91% of Total
            .          .      7:   "sync"
            .          .      8:)
            .          .      9:
            .          .     10:// bigBytes allocates 10 sets of 100 megabytes
            .          .     11:func bigBytes() *[]byte {
    953.75MB   953.75MB     12:   s := make([]byte, 100000000)
            .          .     13:   return &s
            .          .     14:}
            .          .     15:
            .          .     16:func main() {
            .          .     17:   var wg sync.WaitGroup
注意:如果指明要查看在用内存,可以采用如下命令:go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap

可以根据自己的需要,选择-inuse_space或者-alloc_space标签。例如,在考察垃圾回收的性能时,你需要的就是-alloc_space

注意:要考察生成对象的数量,可以用-inuse_objects-alloc_objects标签。

生成图像

要生成分析图像可以使用-png-gif-svg标签,重定向 stdout 到文件:

go tool pprof -png http://localhost:6060/debug/pprof/heap > data.png

产生类似于下面的图片(注意看方框的大小,方框越大表示消耗的资源越多,你可以马上识别出潜在的问题区域):

GO的花式调优技术插图1
注意:可以用-pdf标签产生 PDF 文件。

Web UI 界面

不久后,pprof 分析会新增一个交互式的 web 界面(大概在 2017 年 11 月份)。

更多信息请参考这篇文章

简言之,你可以从 GitHub 获取最新的 pprof 工具,使用的时候加入-http标签(例如,-http=:8080

Trace 跟踪

Trace是一款可视化的工具,用于分析跟踪(trace)数据。它适用于分析程序在各时点的行为,而不是提供一个总体信息。

注意:如果要追查执行慢的函数或者占用 CPU 时间最多的代码,你还是要用go tool pprof命令。

要使用 Trace ,先要对程序进行调整:

func main() {
    trace.Start(os.Stdout)
    defer trace.Stop()

    for i := 0; i < 10; i++ {
        s := bigBytes()
        if s == nil {
            log.Println("oh noes")
        }
    }

    var wg sync.WaitGroup
    wg.Add(1)

    var result []byte
    go func() {
        result = make([]byte, 500000000)
        log.Println("done here")
        wg.Done()
    }()

    wg.Wait()
    log.Printf("%T", result)
}

要用 trace 追踪功能,你只要导入"runtime/trace",然后调用trace.Starttrace.Stop函数。(为了追踪程序的所有内容,在trace.Stop函数前加入defer

此外,我们创建了一个 go 协程,在其中创建了一个 500MB 的切片。等待 go 协程执行完成,然后记录 result 的类型。这样做可以看到更多的直观数据。

现在重新编译程序,用 trace 打开产生的追踪数据:

$ go build -o app
$ time ./app > app.trace
$ go tool trace app.trace
注意:使用-pprof标签,可以生成 pprof 兼容的文件(比如要动态地检查数据时)。更多信息请参考go documentation

这里是执行go tool trace app.trace的输出内容:

2017/10/29 09:30:40 Parsing trace...
2017/10/29 09:30:40 Serializing trace...
2017/10/29 09:30:40 Splitting trace...
2017/10/29 09:30:40 Opening browser

默认的浏览器会自动打开下面的地址:http://127.0.0.1:60331

注意:最好用 Chrome 浏览器,因为兼容性最好。

浏览器的页面上会有如下的链接:

  • View trace
  • Goroutine analysis
  • Network blocking profile
  • Synchronization blocking profile
  • Syscall blocking profile
  • Scheduler latency profile

这些选项链接可以帮助我们更深入理解程序的行为,但我们最关注的是view trace(查看追踪信息)。 点击链接出现一个交互图形,它是应用程序行为的一个完整概览。

GO的花式调优技术插图3
注意:按出现快捷键,比如,ws分别表示放大和缩小。

Go 协程

如果图形放大到足够大,你可以看到 goroutines(go 协程)这一部分,它由两种颜色构成:浅绿色(可运行 go 协程)和深绿色(正在运行的 go 协程)。如果你点击图形,在屏幕下方的预览中,可以看到样例的明细。有趣的是,在任何特定的时刻,会有多个 go 协程存在,但它们不一定同时运行。

在我们的例子中,可以看到程序的变化:从一个准备运行的 go 协程,其并没有真正运行(也就是 runnable 可运行状态),继续向前看到有两个 go 协程在运行。(也就是,两个都处在 running 运行状态,没有 go 协程处于 runnable 状态)

有趣的是,在图中还可以看到,运行中的 go 协程数量与底层操作系统所创建的线程数量之间的关系。

线程

同样的,放大图片你也可以看到 threads(线程)这一部分,它由两种颜色构成:浅紫色(syscalls 系统调用)和深紫色(running threads运行中的线程)。

在界面中 heap 部分有意思的内容是,因为 go 垃圾回收是并发执行,所以我们看到应用程序在堆上从未分配超过 100mb 的内存(go 垃圾回收在不同的进程/线程上运行)。程序运行中,无用的内存就被清理掉了。

这是可以理解的,因为在我们的程序中分配了 100mb 的内存给变量s,这个变量仅在 loop 循环中有效。 一旦 loop 完成一次迭代,s变量就不引用任何地址,所以 GC(垃圾回收)就可以清理掉这块内存。

随着程序继续运行,我们最终会看到一些有冲突的地方,整体的内存分配会变成 200mb ,然后反复在 100mb 和 200mb 之间变化(因为 GC 并不是一直在运行)。当运行到程序的结尾时,我们看到 500mb 的分配尖峰,整体内存分配量达到 600mb 。

但是在这一点时,如果点击堆内存尖峰,在下方的预览窗口,我们可以看到 NextGC 在运行,表明全部内存分配会被清零(因为已经运行到程序的结尾了)。

进程

在界面中 procs 部分,可以看到,在分配 500mb 内存时,Proc 3(进程 3)上有一个新的 go 协程在运行main.main.func1函数(在我们的程序中,这个函数负责内存分配工作)

如果在 View Options(查看选项)中选择 Flow events(流事件),你可以看到一个箭头从main.main函数指向main.main.func1函数,main.main.func1是运行在一个独立的进程/线程上。(箭头不容易看到,但确实有)

GO的花式调优技术插图5

通过图形界面,不但可直观的见到main.main.func1协程运行与内存分配的对应关系,而且能够看到程序的因果关系(也就是,什么触发了新的 go 协程的运行)

结尾

在这个过程中,我们体验了各种各样的 Go 代码调优工具。更多信息可以参考我以前的文章,关于 Python 性能调优的内容。

原创文章 GO的花式调优技术,版权所有
如若转载,请注明出处:https://www.itxiaozhan.cn/20229416.html

发表评论

您的电子邮箱地址不会被公开。 必填项已用*标注