golang的heap profile是抽风了吗

liupenglove

于 2024-05-05 16:18:16 发布

阅读量717

点赞数 29

文章标签： golang 开发语言后端

本文链接：https://blog.csdn.net/liupenglove/article/details/138411582

版权

1、关于pprof

2、heap profile不能准确反应系统内存分配？

3、破案

4、为什么是gc的锅？

5、one more thing

1、关于pprof

pprof是golang内置的性能分析工具，用于分析程序运行时性能瓶颈，可以帮助开发者快速定位到代码中的性能问题，以进行针对性的优化。

通过pprof，我们可以获取到以下性能数据：

总的来说，pprof是一个强大的性能分析工具，可以为程序性能调优提供全面的数据支撑。

2、heap profile不能准确反应系统内存分配？

如下示例代码：

package main

import (
  "fmt"
  "net/http"
  _ "net/http/pprof"
  "os"
  "runtime"
  "runtime/pprof"
  "time"
)

func printMemInfo() {
  for {
    m := runtime.MemStats{}
    runtime.ReadMemStats(&m)
    fmt.Printf("Alloc = %v MiB", m.Alloc/1024/1024)
    fmt.Printf("\tTotal Alloc = %v MiB", m.TotalAlloc/1024/1024)
    fmt.Printf("\tSys = %v MiB", m.Sys/1024/1024)
    fmt.Printf("\tNumGC = %v GCs\n", m.NumGC)
    time.Sleep(2 * time.Second)
  }
}
func main() {
  f, _ := os.OpenFile("mem.profile", os.O_RDWR|os.O_CREATE, 0644)
  defer f.Close()
  go printMemInfo()
  go func() {
    http.ListenAndServe("localhost:8060", nil)
  }()
  sum := [][]int32{}
  time.Sleep(3 * time.Second)
  fmt.Println("============start============")
  for i := 0; i < 10; i++ {
    s := make([]int32, 1024*1024*5)
    sum = append(sum, s)
    time.Sleep(1 * time.Second)
  }
  pprof.Lookup("heap").WriteTo(f, 0)
  fmt.Println("============allocate complete============")
  time.Sleep(30 * time.Second)
  fmt.Print(sum[9][:1])
}

这段代码首先创建了监听8060端口的web服务，目的是通过http来访问heap profile。

然后创建了一个切片，这个切片包含10个元素，每个元素还是一个切片，元素类型为int32，占用4个字节，所以一次for循环里，开辟20MiB的内存，共循环10次，整个程序共使用200MiB内存，实际运行过程中，会稍微大于200MiB，因为程序还有一些其他的开销。

运行程序：

liupeng@liupengdeMacBook-Pro test % go run main.go
Alloc = 0 MiB  Total Alloc = 0 MiB  Sys = 6 MiB  NumGC = 0 GCs
Alloc = 0 MiB  Total Alloc = 0 MiB  Sys = 6 MiB  NumGC = 0 GCs
============start============
Alloc = 20 MiB  Total Alloc = 20 MiB  Sys = 28 MiB  NumGC = 1 GCs
Alloc = 60 MiB  Total Alloc = 60 MiB  Sys = 68 MiB  NumGC = 2 GCs
Alloc = 100 MiB  Total Alloc = 100 MiB  Sys = 108 MiB  NumGC = 3 GCs
Alloc = 140 MiB  Total Alloc = 140 MiB  Sys = 148 MiB  NumGC = 3 GCs
Alloc = 180 MiB  Total Alloc = 180 MiB  Sys = 188 MiB  NumGC = 4 GCs
============allocate complete============
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs
Alloc = 201 MiB  Total Alloc = 201 MiB  Sys = 208 MiB  NumGC = 4 GCs

从运行记录可以看出来，runtime.MemStats统计的内存分配情况还是比较准确的，当内存分配结束后，统计数据马上也到了200MiB，符合预期。

接下来看一下heap profile的数据：

运行命令：

go tool pprof -http=localhost:8080 mem.profile

下方的可视化图片，需要安装：graphviz，mac系统可以直接运行命令安装：

brew install graphviz

问题来了，为什么只有80MiB，其他的120MiB哪里去了呢？开丢了？还是heap profile数据不准确？

3、破案

我们将代码中46行的sleep时间改长一些，大概等上5分钟，之后运行命令：

go tool pprof -http=:8082 "http://127.0.0.1:8060/debug/pprof/heap?debug=2"

我们可以看到，欸？开辟的内存变成160M了，难道是现在内容才开辟完吗？内存申请这么慢吗？答案肯定不是的，这里涉及一个重要的知识点：gc，垃圾回收机制。下面进行验证，在内存申请完成后，强制进行一次gc，代码修改为如下：


package main

import (
  "fmt"
  "net/http"
  _ "net/http/pprof"
  "os"
  "runtime"
  "runtime/pprof"
  "time"
)

func printMemInfo() {
  for {
    m := runtime.MemStats{}
    runtime.ReadMemStats(&m)
    fmt.Printf("Alloc = %v MiB", m.Alloc/1024/1024)
    fmt.Printf("\tTotal Alloc = %v MiB", m.TotalAlloc/1024/1024)
    fmt.Printf("\tSys = %v MiB", m.Sys/1024/1024)
    fmt.Printf("\tNumGC = %v GCs\n", m.NumGC)
    time.Sleep(2 * time.Second)
  }
}
func main() {
  f, _ := os.OpenFile("mem.profile", os.O_RDWR|os.O_CREATE, 0644)
  defer f.Close()
  go printMemInfo()
  go func() {
    http.ListenAndServe("localhost:8060", nil)
  }()
  sum := [][]int32{}
  time.Sleep(3 * time.Second)
  fmt.Println("============start============")
  for i := 0; i < 10; i++ {
    s := make([]int32, 1024*1024*5)
    sum = append(sum, s)
    time.Sleep(1 * time.Second)
  }
  pprof.Lookup("heap").WriteTo(f, 0)
  runtime.GC()
  fmt.Println("============allocate complete============")
  time.Sleep(300 * time.Second)
  fmt.Print(sum[9][:1])
}

在45行增加代码：runtime.GC()

运行代码再探，当代码打印出：『allocate complete』后执行命令：

go tool pprof -http=:8082 "http://127.0.0.1:8060/debug/pprof/heap?debug=2"

可以看到，pprof统计的是妥妥的200MiB内存。

到这里我们已经可以肯定是gc导致的，如果是对线上服务进行统计，肯定也不能随心所欲的强制gc，不过没关系，我们只需要在访问heap profile时增加【gc=1】这个参数就可以啦，现在我们将代码45行的强制gc删掉，运行程序，当内存分配完成后，运行命令：

go tool pprof -http=:8082 "http://127.0.0.1:8060/debug/pprof/heap?gc=1&debug=2"

这个时候你应该就看到结果，200M，肯定是没问题的。

4、为什么是gc的锅？

heap profile的数据来源，本质上还是来自runtime.MemProfile的数据，但为什么会出现问题呢，原因在这个函数：

func MemProfile(p []MemProfileRecord, inuseZero bool) (n int, ok bool)

这个函数的说明里有下面一段话：

The returned profile may be up to two garbage collection cycles old. This is to avoid skewing the profile toward allocations; because allocations happen in real time but frees are delayed until the garbage collector performs sweeping, the profile only accounts for allocations that have had a chance to be freed by the garbage collector.

大概的意思就是说，返回的性能数据是两个gc之前的数据，这样做的目的是为了避免产生偏差，内存的分配是实时发生的，但释放是在进行gc时才进行，性能分析只会统计那些有机会被回收的内存。

system.gc会强制进行内存回收，并生成新的profile，所以是可以马上看到200M的内存。

5、one more thing

我们需要重点关注下：

runtime.MemProfileRate

这个变量为分析器的取样间隔，默认值为：512K，其决定了内存分析器进行记录的时机，当内存分配每达到MemProfileRate 大小时，就会记录一次，因此我理解，这个值越小，意味着更频繁的记录内存分配信息，从而产生更精细的内存分析数据，但是也会增加系统的性能开销。相反，这个值越大，会减少性能开销，但也会减少内存分析的精度。

注意，如果你要设定这个采样频率，那么越早设定越好，并且只应该设定一次，否则就可能会对 Go 语言运行时系统的采样工作，造成不良影响。比如，只在main函数的开始处设定一次。

还是上面的代码，我们每次分配内存改小一些，不能被512K整除，这样实时统计与pprof就会产生一定的偏差：


package main

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

func printMemInfo() {
  for {
    m := runtime.MemStats{}
    runtime.ReadMemStats(&m)
    fmt.Printf("Alloc = %v MiB", m.Alloc/1024/1024)
    fmt.Printf("\tTotal Alloc = %v MiB", m.TotalAlloc/1024/1024)
    fmt.Printf("\tSys = %v MiB", m.Sys/1024/1024)
    fmt.Printf("\tNumGC = %v GCs\n", m.NumGC)
    time.Sleep(2 * time.Second)
  }
}
func main() {
  go printMemInfo()
  go func() {
    http.ListenAndServe("localhost:8060", nil)
  }()
  sum := [][]int32{}
  time.Sleep(3 * time.Second)
  fmt.Println("============start============")
  for i := 0; i < 1000; i++ {
    s := make([]int32, 1024*60)
    sum = append(sum, s)
    // time.Sleep(1 * time.Second)
  }
  // runtime.GC()
  // pprof.Lookup("heap").WriteTo(f, 0)
  fmt.Println("============allocate complete============")
  time.Sleep(300 * time.Second)
  fmt.Print(sum[1024][:1])
}

代码运行记录：

liupeng@liupengdeMacBook-Pro test % go run main.go
Alloc = 0 MiB  Total Alloc = 0 MiB  Sys = 6 MiB  NumGC = 0 GCs
Alloc = 0 MiB  Total Alloc = 0 MiB  Sys = 6 MiB  NumGC = 0 GCs
============start============
============allocate complete============
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 6 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 6 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs
Alloc = 234 MiB  Total Alloc = 234 MiB  Sys = 245 MiB  NumGC = 7 GCs

pprof数据：