Go语言调试及性能分析

深入理解Go语言
Golang
发布日期:   2023-08-10
更新日期:   2023-08-12
文章字数:   2.5k
阅读时长:   11 分

写程序的时候经常需要我们分析程序运行的性能、debug，本篇文章将通过几个场景介绍几个相关工具的简单使用。

分析程序的运行时间和CPU利用率

shell内置的time指令

假如我们有一个go程序：

package main

import "fmt"

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

我们通过time go run main.go即可获取程序运行时间的相关信息：

image-20230811102705973

  • real：程序开始到结束经过的时间
  • user：程序在用户态度过的时间
  • sys：程序在内核态度过的时间

一般情况下，$real\ge user+sys$，因为操作系统中还有其它进程，进程切换时会有空白期。

/usr/bin/time指令

这个指令比内置的time获得的信息更详细，使用时需要带上-v参数，使用/usr/bin/time -v go run main.go ，获取信息如下：

Command being timed: "go run main.go"
User time (seconds): 0.18
System time (seconds): 0.03
Percent of CPU this job got: 117% # CPU占用率
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.18 # 程序开始到结束系统时钟走过的时间
Average shared text size (kbytes): 0
Average unshared data size (kbytes): 0
Average stack size (kbytes): 0
Average total size (kbytes): 0
Maximum resident set size (kbytes): 41596 # 执行程序所占用内存的最大值
Average resident set size (kbytes): 0
# page fault情况
Major (requiring I/O) page faults: 288
Minor (reclaiming a frame) page faults: 12644
# 进程切换情况
Voluntary context switches: 885
Involuntary context switches: 58
Swaps: 0
# 文件系统IO
File system inputs: 1216
File system outputs: 2312
# socket使用情况
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0

分许程序的内存使用情况

内存占用情况的查看

给出以下实例代码：

package main

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

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

    log.Println(" ===> loop begin.")
    for i := 0; i < 32*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 memory.go 生成可执行程序，并./memory运行。

然后再开一个窗口通过top -p $(pidof memory)查看该进程的内存占用等情况：

image-20230812095631830

我们发现该进程占用了900多兆内存，奇怪，我们已经调用了GC，按理说内存应该都回收了，让我们通过调试查看详细的情况。

GODEBUG与gctrace

设置环境变量并执行：GODEBUG='gctrace=1' ./memory，这会使得垃圾回收器在每次回收时汇总所回收内存的大小以及耗时并打印到stderr中。

image-20230812100140151

输出了这类内容，格式：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 18 @0.175s 5%: 0.021+42+0.010 ms clock, 0.086+0/0.11/42+0.041 ms cpu, 346->346->211 MB, 346 MB goal, 0 MB stacks, 0 MB globals, 4 P

  • gc 18: Gc 调试编号为18
  • @0.175s:此时程序已经执行了0.175s
  • 5%: 0.175s中其中gc模块占用了5%的时间
  • 0.021+42+0.010 ms clock: 垃圾回收的时间，分别为STW清扫的时间+并发标记和扫描的时间+STW标记的时间
  • 0.086+0/0.11/42+0.041 ms cpu: 垃圾回收占用cpu时间
  • 346->346->211 MB： GC开始前堆内存346， GC结束后堆内存346，当前活跃的堆内存211M
  • 346 MB goal: 全局堆内存大小
  • 4 P: 本次GC使用了2个P(调度器中的Processer)
  • GC forced: 如果两分钟内没有执行GC，会强制执行一次GC，会换行打印 GC forced

那为什么GC没有回收变量呢？我们查看相关输出：

image-20230812101110333

我们发现，我们手动调用的那次GC就已经把516M的堆内存标记为非活跃内存，再看下一条记录，全局堆内存已经下降到了4M，说明：

  • 在test()函数执行完后，程序中的切片容器所申请的堆空间都被垃圾回收器回收了
  • 垃圾回收器回收了应用层的内存后，（可能）并不会立即将内存归还给系统。

runtime.ReadMemStats

这是一个Go语言库提供的方法，我们用以下示例程序：

package main

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

func readMemStats() { // 读取内存信息,log打印

    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) //睡眠，保持程序不退出
}

生成可执行程序并运行，观察输出：

image-20230812102229630

在打印[Done]之后，Alloc开始下降，说明内存已被GC回收，随后HeapReleased又开始上升，说明此时GC开始把内存归还给操作系统。

pprof工具

这是一个支持在网页上查看内存使用情况的工具，使用示例如下：

package main

import (
    "log"
    "runtime"
    "time"
    "net/http"
    _ "net/http/pprof"
    // 由于我们没有在程序中直接调用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-20230812103807353

分析程序的CPU性能情况

我们使用如下代码测试：

package main

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


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)
        }
    }()

    //启动pprof
    http.ListenAndServe("0.0.0.0:10000", nil)

}

我们在程序中一直随机生成字符串，接下来我们通过几种方式查看进程的cpu性能情况。

Web界面查看

运行程序，浏览器访问http://127.0.0.1:10000/debug/pprof/，我们会看到如下画面：

image-20230812104247740

这里面能够通过pprof查看包括（阻塞信息、cpu信息、内存堆信息、锁信息、goroutine信息等等）， 我们这里关心cpu性能的profile信息。看英文，我们发现，他需要我们获取当前进程的profile文件，默认是30s生成一个，我们可以修改（后面介绍）。我们可以直接点击网页的profile，浏览器会给我们下载一个profile文件。记住这个文件的路径，拷贝到当前目录下。

使用pprof工具查看

指令格式：go tool pprof [binary] [profile]，其中[binary]即是我们的可执行程序，而[profile]即是我们刚刚下载的profile文件。binary 和 profile 必须对应。

执行go tool pprof ./cpu profile得到如下输出：

image-20230812105240694

help可以查看指令，我们可以通过top指令获取cpu相关的信息：

(pprof) top
Showing nodes accounting for 5090ms, 81.18% of 6270ms total
Dropped 80 nodes (cum <= 31.35ms)
Showing top 10 nodes out of 60
      flat  flat%   sum%        cum   cum%
    1060ms 16.91% 16.91%     2170ms 34.61%  math/rand.(*lockedSource).Int63
     850ms 13.56% 30.46%      850ms 13.56%  sync.(*Mutex).Unlock (inline)
     710ms 11.32% 41.79%     2950ms 47.05%  math/rand.(*Rand).Int31n
     570ms  9.09% 50.88%      990ms 15.79%  bytes.(*Buffer).Write
     530ms  8.45% 59.33%      540ms  8.61%  syscall.Syscall
     370ms  5.90% 65.23%      370ms  5.90%  runtime.procyield
     270ms  4.31% 69.54%     4490ms 71.61%  main.genSomeBytes
     250ms  3.99% 73.52%     3200ms 51.04%  math/rand.(*Rand).Intn
     250ms  3.99% 77.51%      250ms  3.99%  runtime.memmove
     230ms  3.67% 81.18%      690ms 11.00%  runtime.suspendG
(pprof)
  • flat：当前函数占用CPU的耗时
  • flat%：:当前函数占用CPU的耗时百分比
  • sum%：函数占用CPU的耗时累计百分比
  • cum：当前函数加上调用当前函数的函数占用CPU的总耗时
  • cum%：当前函数加上调用当前函数的函数占用CPU的总耗时百分比
  • 最后一列：函数名称

我们可以看出， 该程序的大部分cpu性能消耗在 main.getSomeBytes()方法中，其中math/rand取随机数消耗比较大。

通过go tool pprof得到profile文件

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

我们先启动程序：./cpu

然后在同目录下再开一个终端：go tool pprof http://localhost:10000/debug/pprof/profile?seconds=60

等待60s之后，第二个终端就会有结果出来，我们继续使用top即可查看。

可视化查看

在go tool pprof ./cpu profile之后我们输入web指令，若报错找不到graphviz，就先安装。

Ubuntu安装：sudo apt-get install graphviz

然后我们就会得到一个svg的可视化文件在/tmp路径下：

image-20230812110116990

可以清楚地看到函数间调用关系，且方框越大，cpu占用越大。

文章作者: verynewabie
文章链接: http://verynewabie.github.io/2023/08/10/go-yu-yan-diao-shi-ji-xing-neng-fen-xi/
版权声明: 本博客所有文章除特別声明外，均采用 CC BY 4.0 许可协议。转载请注明来源 verynewabie !
深入理解Go语言
评论
  目录