Golang 调试与性能

長夜難明
225 阅读4分钟

1. 如何分析程序的运行时间与CPU利用率情况？

1.1 shell自带的time指令

time go run xxx.go

image.png

  • real：从程序开始到结束，实际度过的时间；
  • user：程序在用户态度过的时间；
  • sys：程序在内核态度过的时间。

一般情况下 real >= user + sys，因为系统还有其它进程(进程切换占用时间)。

1.2 /usr/bin/time指令

使用时需要用绝对路径，加上参数-v

/usr/bin/time go run xxx.go

image.png

2. 如何分析golang程序的内存使用情况？

2.1 demo引入

package main

import (
    "log"
    "runtime"
    "time"
)

func test() {
    //slice 会动态扩容，用slice来做堆内存申请
    container := make([]int, 8)

    log.Println(" ===> loop begin.")
    for i := 0; i < 32*1000*1000; i++ {
        container = append(container, i)
    }
    log.Println(" ===> loop end.")
}

func main() {
    log.Println("Start.")

    test()

    log.Println("force gc.")
    runtime.GC() //强制调用gc回收

    log.Println("Done.")

    time.Sleep(3600 * time.Second) //睡眠，保持程序不退出
}

编译，运行

go build -o mem ./main.go

./mem

在./mem进程没有执行完时，再开一个窗口，通过top命令查看进程的内存占用情况

top -p $(pidof mem)

image.png

进程占用了1G内存。

按理说程序在test()函数执行完后，切片contaner的内存应该被释放，不应该占用1G那么大。

下面让我们使用GODEBUG来分析程序的内存使用情况。

2.2 GODEBUG与gctrace

执行mem程序之前添加环境变量GODEBUG='gctrace=1'来跟踪打印垃圾回收器信息

$ GODEBUG='gctrace=1' ./mem

设置gctrace=1会使得垃圾回收器在每次回收时汇总所回收内存的大小以及耗时，并将这些内容汇总成单行内容打印到标准错误输出中。

格式

gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P

含义

	gc #        GC次数的编号，每次GC时递增
	@#s         距离程序开始执行时的时间
	#%          GC占用的执行时间百分比
	#+...+#     GC使用的时间
	#->#-># MB  GC开始，结束，以及当前活跃堆内存的大小，单位M
	# MB goal   全局堆内存大小
	# P         使用processor的数量

如果每条信息最后，以(forced)结尾，那么该信息是由runtime.GC()调用触发

我们选择其中一行来解释一下：

gc 17 @0.149s 1%: 0.004+36+0.003 ms clock, 0.009+0/0.051/36+0.006 ms cpu, 181->181->101 MB, 182 MB goal, 2 P
  • gc 17: Gc 调试编号为17
  • @0.149s:此时程序已经执行了0.149s
  • 1%: 0.149s中其中gc模块占用了1%的时间
  • 0.004+36+0.003 ms clock: 垃圾回收的时间，分别为STW清扫的时间+并发标记和扫描的时间+STW标记的时间
  • 0.009+0/0.051/36+0.006 ms cpu: 垃圾回收占用cpu时间
  • 181->181->101 MB： GC开始前堆内存181M， GC结束后堆内存181M，当前活跃的堆内存101M
  • 182 MB goal: 全局堆内存大小
  • 2 P: 本次GC使用了2个P(调度器中的Processer)

image.png

分析

test()函数执行完后打印的gc 17那行的信息。516->516->0 MB, 1032 MB goal表示垃圾回收器已经把516M的内存标记为非活跃的内存。

再看下一个记录gc 18。0->0->0 MB, 4 MB goal表示垃圾回收器中的全局堆内存大小由1032M下降为4M。

结论
1、在test()函数执行完后，demo程序中的切片容器所申请的堆空间都被垃圾回收器回收了。
2、如果此时在top指令查询内存的时候，如果依然是800+MB，说明垃圾回收器回收了应用层的内存后，（可能）并不会立即将内存归还给系统。

2.3 runtime.ReadMemStats

换一种方式查看内存

package main

import (
    "log"
    "runtime"
    "time"
)

func readMemStats() {

    var ms runtime.MemStats

    runtime.ReadMemStats(&ms)

    log.Printf(" ===> Alloc:%d(bytes) HeapIdle:%d(bytes) HeapReleased:%d(bytes)", ms.Alloc, ms.HeapIdle, ms.HeapReleased)
}

func test() {
    //slice 会动态扩容，用slice来做堆内存申请
    container := make([]int, 8)

    log.Println(" ===> loop begin.")
    for i := 0; i < 32*1000*1000; i++ {
        container = append(container, i)
        if ( i == 16*1000*1000) {
            readMemStats()
        }
    }

    log.Println(" ===> loop end.")
}

func main() {
    log.Println(" ===> [Start].")

    readMemStats()
    test()
    readMemStats()

    log.Println(" ===> [force gc].")
    runtime.GC() //强制调用gc回收

    log.Println(" ===> [Done].")
    readMemStats()

    go func() {
        for {
            readMemStats()
            time.Sleep(10 * time.Second)
        }
    }()

    time.Sleep(3600 * time.Second) //睡眠，保持程序不退出
}

封装函数readMemStats()，调用runtime中的ReadMemStats()方法获得内存信息，通过log打印出来。

image.png

可以看到，打印[Done].之后那条trace信息，Alloc已经下降，即内存已被垃圾回收器回收。在最后两条trace信息中，HeapReleased开始上升，即垃圾回收器把内存归还给系统。

2.4 pprof工具

在原先代码中添加个携程启动pprof即可

package main

import (
    "log"
    "runtime"
    "time"
    "net/http"
    _ "net/http/pprof"
)

func readMemStats() {

    var ms runtime.MemStats

    runtime.ReadMemStats(&ms)

    log.Printf(" ===> Alloc:%d(bytes) HeapIdle:%d(bytes) HeapReleased:%d(bytes)", ms.Alloc, ms.HeapIdle, ms.HeapReleased)
}

func test() {
    //slice 会动态扩容，用slice来做堆内存申请
    container := make([]int, 8)

    log.Println(" ===> loop begin.")
    for i := 0; i < 32*1000*1000; i++ {
        container = append(container, i)
        if ( i == 16*1000*1000) {
            readMemStats()
        }
    }

    log.Println(" ===> loop end.")
}

func main() {
    //启动pprof
    go func() {
        log.Println(http.ListenAndServe("0.0.0.0:10000", nil))
    }()

    log.Println(" ===> [Start].")

    readMemStats()
    test()
    readMemStats()

    log.Println(" ===> [force gc].")
    runtime.GC() //强制调用gc回收

    log.Println(" ===> [Done].")
    readMemStats()

    go func() {
        for {
            readMemStats()
            time.Sleep(10 * time.Second)
        }
    }()

    time.Sleep(3600 * time.Second) //睡眠，保持程序不退出
}

正常运行程序，同时打开：http://127.0.0.1:10000/debug/pprof/heap?debug=1

浏览器的内容其中有一部分如下，记录了目前的内存情况

image.png

3. 如何分析Golang程序的CPU性能情况？

package main

import (
	"bytes"
	"log"
	"math/rand"
	"net/http"
	_ "net/http/pprof"
	"time"
)

func test() {

    log.Println(" ===> loop begin.")
    for i := 0; i < 1000; i++ {
        log.Println(genSomeBytes())
    }
    log.Println(" ===> loop end.")
}

//生成一个随机字符串
func genSomeBytes() *bytes.Buffer {
    var buff bytes.Buffer
    for i := 1; i < 20000; i++ {
        buff.Write([]byte{'0' + byte(rand.Intn(10))})
    }

    return &buff
}

func main() {
    go func() {
        for {
            test()
            time.Sleep(time.Second * 1)
        }
    }()
    http.ListenAndServe("0.0.0.0:10000", nil)
}

main()里的流程很简单,启动一个goroutine去无限循环调用test()方法,休眠1s.

test()的流程是生成1000个20000个字符的随机字符串.并且打印.

我们将上面的代码编译成可执行的二进制文件 demo

go build -o demo ./main.go

启动程序,无限循环的打印字符串.

接下来我们通过几种方式来查看进程的cpu性能情况.

3.1 Web界面查看

浏览器访问http://127.0.0.1:10000/debug/pprof/

这里面能够通过pprof查看包括(阻塞信息、cpu信息、内存堆信息、锁信息、goroutine信息等等)

image.png

我们要是想得到cpu性能,就是要获取到当前进程的profile文件,这个文件默认是30s生成一个,所以你的程序要至少运行30s以上(参数也可以修改,稍后我们介绍)

我们可以直接点击网页的profile,浏览器会给我们下载一个profile文件.

把profile文件和demo文件放一个目录下

3.2 使用pprof工具查看

go tool pprof [binary] [profile]

go tool pprof demo profile

image.png

可以通过top查看cpu详细情况

image.png

  • flat：当前函数占用CPU的耗时
  • flat%：:当前函数占用CPU的耗时百分比
  • sum%：函数占用CPU的耗时累计百分比
  • cum：当前函数加上调用当前函数的函数占用CPU的总耗时
  • cum%：当前函数加上调用当前函数的函数占用CPU的总耗时百分比
  • 最后一列：函数名称

3.3 通过go tool pprof得到profile文件

上面的profile文件是通过web浏览器下载的,这个profile的经过时间是30s的,默认值我们在浏览器上修改不了,如果你想得到时间更长的cpu利用率,可以通过go tool pprof指令与程序交互来获取到

首先启动程序后打开一个新的终端

go tool pprof http://localhost:10000/debug/pprof/profile?seconds=60

这里制定了生成profile文件的时间间隔60s

60s之后, 终端就会有结果出来，可以使用top来查看.

3.4 可视化查看

yum install graphviz

进入profile文件查看,输入web指令.

go tool pprof demo profile

(pprof) web

image.png

这样我们就能比较清晰的看到函数之间的调用关系,方块越大的表示cpu的占用越大.

转自最常用的调试 golang 的 bug 以及性能问题的实践方法 (yuque.com)

avatar
文章
阅读
粉丝