AI 助理
备案控制台
开发者社区 开发与运维 文章 正文

Golang内存分析工具gctrace和pprof实战

2024-08-29 82
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
简介： 文章详细介绍了Golang的两个内存分析工具gctrace和pprof的使用方法，通过实例分析展示了如何通过gctrace跟踪GC的不同阶段耗时与内存量对比，以及如何使用pprof进行内存分析和调优。

gctrace

gctrace用途主要是用于跟踪GC的不同阶段的耗时与GC前后的内存量对比。

使用的时候仅需在启动的时候添加GODEBUG='gctrace=1'的命令参数即可。如下

➜  server git:(master) GODEBUG='gctrace=1' go run ./cmd/main.go
gc 1 @0.024s 1%: 0.027+1.0+0.022 ms clock, 0.21+1.1/0.58/0.008+0.17 ms cpu, 4->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 2 @0.031s 1%: 0.022+0.59+0.032 ms clock, 0.18+0.64/0.74/0.12+0.26 ms cpu, 4->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 3 @0.038s 1%: 0.012+0.41+0.014 ms clock, 0.096+0.22/0.46/0+0.11 ms cpu, 4->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 4 @0.047s 1%: 0.057+0.32+0.012 ms clock, 0.45+0.35/0.37/0.003+0.097 ms cpu, 4->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 5 @0.053s 1%: 0.024+0.31+0.022 ms clock, 0.19+0.18/0.46/0.054+0.17 ms cpu, 4->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 6 @0.058s 1%: 0.025+0.52+0.038 ms clock, 0.20+0.53/0.46/0+0.30 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 7 @0.063s 1%: 0.037+0.46+0.014 ms clock, 0.30+0.20/0.60/0+0.11 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 8 @0.070s 1%: 0.026+0.32+0.002 ms clock, 0.21+0.097/0.54/0.19+0.016 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 9 @0.077s 1%: 0.030+0.39+0.018 ms clock, 0.24+0.068/0.41/0.16+0.14 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 10 @0.083s 1%: 0.027+0.46+0.005 ms clock, 0.21+0.46/0.55/0.012+0.042 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 11 @0.087s 2%: 0.039+0.44+0.018 ms clock, 0.31+0.26/0.62/0+0.14 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 12 @0.093s 2%: 0.026+0.43+0.003 ms clock, 0.21+0.40/0.47/0+0.030 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P

参数说明

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

where the fields are as follows:

gc # the GC number, incremented at each GC

@#s time in seconds since program start

% percentage of time spent in GC since program start

+...+# wall-clock/CPU times for the phases of the GC

->#-># MB heap size at GC start, at GC end, and live heap

# MB goal goal heap size

# P number of processors used

The phases are stop-the-world (STW) sweep termination, concurrent

mark and scan, and STW mark termination. The CPU times

for mark/scan are broken down in to assist time (GC performed in

line with allocation), background GC time, and idle GC time.

If the line ends with "(forced)", this GC was forced by a

runtime.GC() call and all phases are STW.

举例分析

gc 12 @0.093s 2%: 0.026+0.43+0.003 ms clock, 0.21+0.40/0.47/0+0.030 ms cpu, 4->4->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P

gc 12： 这是第12次gc。

@0.093s： 这次gc的markTermination阶段完成后，距离runtime启动到现在的时间。

2%：当目前为止，gc的标记工作（包括两次mark阶段的STW和并发标记）所用的CPU时间占总CPU的百分比。

0.026+0.43+0.003 ms clock：按顺序分成三部分，0.026表示mark阶段的STW时间（单P的）；0.43表示并发标记用的时间（所有P的）；0.003表示markTermination阶段的STW时间（单P的）。

0.21+0.40/0.47/0+0.030 ms cpu：按顺序分成三部分，0.21表示整个进程在mark阶段STW停顿时间(0.026 * 8)；0.40/0.47/0有三块信息，0.40是mutator assists占用的时间，0.47是dedicated mark workers+fractional mark worker占用的时间，0是idle mark workers占用的时间。这三块时间加起来会接近0.43*8(P的个数)；0.030 ms表示整个进程在markTermination阶段STW停顿时间(0.003 * 8)。

4->4->1 MB：按顺序分成三部分，4表示开始mark阶段前的heap_live大小；4表示开始markTermination阶段前的heap_live大小；1表示被标记对象的大小。

4 MB goal：表示下一次触发GC的内存占用阀值是4MB，等于2MB * 2，向上取整。

8 P：本次gc共有多少个P。

补充说明

一、heap_live要结合go的内存管理来理解。因为go按照不同的对象大小，会分配不同页数的span。span是对内存页进行管理的基本单元，每页8k大小。所以肯定会出现span中有内存是空闲着没被用上的。

不过怎么用go先不管，反正是把它划分给程序用了。而heap_live就表示所有span的大小。

而程序到底用了多少呢？就是在GC扫描对象时，扫描到的存活对象大小就是已用的大小。对应上面就是4MB。

二、mark worker分为三种，dedicated、fractional和idle。分别表示标记工作干活时的专注程度。dedicated最专注，除非被抢占打断，否则一直干活。idle最偷懒，干一点活就退出，控制权让给出别的goroutine。它们都是并发标记工作里的worker。

pprof

平时在工程中使用，需要通过go func来触发，此处专门抽取出来进行分析

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

func TestPprof(t *testing.T) {
   
   
   http.ListenAndServe("0.0.0.0:8899", nil)
}

在浏览器中输入http://127.0.0.1:8899/debug/pprof/可以看到一个汇总页面，

页面显示如下：

其中heap项是我们需要关注的信息，进入页面可以看到信息如下，

包括一些汇总信息和各个go routine的内存开销，不过这里除了第一行信息比较直观，其他的信息太离散。

heap profile: 2(inused_objects): 1568(inused_bytes) [2(allocated_objects): 1568(allocted_bytes)] @ heap/1048576

go tool pprof分析工具

➜  ~ go tool pprof -inuse_space http://127.0.0.1:8899/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:8899/debug/pprof/heap
Saved profile in /Users/shareit/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
Type: inuse_space
Time: Jul 28, 2022 at 2:10pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

有两个选项，-alloc_space和-inuse_space，优先使用-inuse_space来分析，因为直接分析导致问题的现场比分析历史数据肯定要直观的多，一个函数alloc_space多不一定就代表它会导致进程的RSS高，因为我们比较幸运可以在线下复现这个OOM的场景，所以直接用-inuse_space。

这个命令进入后，是一个类似gdb的交互式界面，输入top命令可以前10大的内存分配，

(pprof) top
Showing nodes accounting for 2049.89kB, 100% of 2049.89kB total
Showing top 10 nodes out of 15
flat  flat%   sum%        cum   cum%
1537.69kB 75.01% 75.01%  1537.69kB 75.01%  runtime.allocm
512.20kB 24.99%   100%   512.20kB 24.99%  runtime.malg
0     0%   100%  1025.12kB 50.01%  runtime.mcall
0     0%   100%   512.56kB 25.00%  runtime.mstart
0     0%   100%   512.56kB 25.00%  runtime.mstart0
0     0%   100%   512.56kB 25.00%  runtime.mstart1
0     0%   100%  1537.69kB 75.01%  runtime.newm
0     0%   100%   512.20kB 24.99%  runtime.newproc.func1
0     0%   100%   512.20kB 24.99%  runtime.newproc1
0     0%   100%  1025.12kB 50.01%  runtime.park_m

flat是堆栈中当前层的inuse内存值，cum是堆栈中本层级的累计inuse内存值（包括调用的函数的inuse内存值，上面的层级），

可以看到目前内存都是未被使用的，而且都来自runtime的分配。此处如果发现flat%列占比较高，则可以继续利用list命令进行深入追踪。

(pprof) list malg
Total: 2MB
ROUTINE ======================== runtime.malg in /Users/shareit/Workspace/work/service/go/src/runtime/proc.go
512.20kB   512.20kB (flat, cum) 24.99% of Total
.          .   4029:    execLock.unlock()
.          .   4030:}
.          .   4031:
.          .   4032:// Allocate a new g, with a stack big enough for stacksize bytes.
.          .   4033:func malg(stacksize int32) *g {
   
   
512.20kB   512.20kB   4034:    newg := new(g)
.          .   4035:    if stacksize >= 0 {
   
   
.          .   4036:        stacksize = round2(_StackSystem + stacksize)
.          .   4037:        systemstack(func() {
   
   
.          .   4038:            newg.stack = stackalloc(uint32(stacksize))
.          .   4039:        })

可以直接看到哪个函数在哪一行代码产生了多少的内存！

不过如果可以导出文件的测试环境就更方便了。

➜  ~ go tool pprof -inuse_space -cum -svg http://127.0.0.1:8899/debug/pprof/heap > ~/Desktop/heap_inuse.svg
Fetching profile over HTTP from http://127.0.0.1:8899/debug/pprof/heap
Saved profile in /Users/shareit/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable file not found in $PATH

说明没有安装graphviz，通过brew安装

➜  ~ brew install graphviz
Running brew update --auto-update...
==> Auto-updated Homebrew!

➜  ~ go tool pprof -inuse_space -cum -svg http://127.0.0.1:8899/debug/pprof/heap > ~/Desktop/heap_inuse.svg
Fetching profile over HTTP from http://127.0.0.1:8899/debug/pprof/heap
Saved profile in /Users/shareit/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz

这次成功输出，我们打开图片如下

参考

文章标签：
Java
Go
测试技术
NoSQL
关键词：
内存分析
内存工具
内存工具实战
内存实战
Golang实战
FeelTouchLabs
目录
相关文章
我是快乐的嘟嘟
|
10天前
|
Web App开发 监控 JavaScript
监控和分析 JavaScript 内存使用情况
【10月更文挑战第30天】通过使用上述的浏览器开发者工具、性能分析工具和内存泄漏检测工具，可以有效地监控和分析JavaScript内存使用情况，及时发现和解决内存泄漏、过度内存消耗等问题，从而提高JavaScript应用程序的性能和稳定性。在实际开发中，可以根据具体的需求和场景选择合适的工具和方法来进行内存监控和分析。
我是快乐的嘟嘟
27 2
禁默
|
1月前
|
编译器 C语言
动态内存分配与管理详解（附加笔试题分析）（上）
动态内存分配与管理详解（附加笔试题分析）
禁默
49 1
路边两盏灯
|
5天前
|
开发框架 监控 .NET
【Azure App Service】部署在App Service上的.NET应用内存消耗不能超过2GB的情况分析
x64 dotnet runtime is not installed on the app service by default. Since we had the app service running in x64, it was proxying the request to a 32 bit dotnet process which was throwing an OutOfMemoryException with requests >100MB. It worked on the IaaS servers because we had the x64 runtime install
路边两盏灯
24 5
mao29955
|
15天前
|
Web App开发 JavaScript 前端开发
使用 Chrome 浏览器的内存分析工具来检测 JavaScript 中的内存泄漏
【10月更文挑战第25天】利用 Chrome 浏览器的内存分析工具，可以较为准确地检测 JavaScript 中的内存泄漏问题，并帮助我们找出潜在的泄漏点，以便采取相应的解决措施。
mao29955
103 9
aliyun0942992302
|
19天前
|
并行计算 算法 IDE
【灵码助力Cuda算法分析】分析共享内存的矩阵乘法优化
本文介绍了如何利用通义灵码在Visual Studio 2022中对基于CUDA的共享内存矩阵乘法优化代码进行深入分析。文章从整体程序结构入手，逐步深入到线程调度、矩阵分块、循环展开等关键细节，最后通过带入具体值的方式进一步解析复杂循环逻辑，展示了通义灵码在辅助理解和优化CUDA编程中的强大功能。
aliyun0942992302
68 2
喜欢猪猪
|
30天前
|
存储 监控 算法
JVM调优深度剖析：内存模型、垃圾收集、工具与实战
【10月更文挑战第9天】在Java开发领域，Java虚拟机（JVM）的性能调优是构建高性能、高并发系统不可或缺的一部分。作为一名资深架构师，深入理解JVM的内存模型、垃圾收集机制、调优工具及其实现原理，对于提升系统的整体性能和稳定性至关重要。本文将深入探讨这些内容，并提供针对单机几十万并发系统的JVM调优策略和Java代码示例。
喜欢猪猪
46 2
禁默
|
1月前
|
程序员 编译器 C语言
动态内存分配与管理详解（附加笔试题分析）（下）
动态内存分配与管理详解（附加笔试题分析）（下）
禁默
45 2
尹正杰
|
2月前
|
Go
Golang语言之管道channel快速入门篇
这篇文章是关于Go语言中管道（channel）的快速入门教程，涵盖了管道的基本使用、有缓冲和无缓冲管道的区别、管道的关闭、遍历、协程和管道的协同工作、单向通道的使用以及select多路复用的详细案例和解释。
尹正杰
106 4
Golang语言之管道channel快速入门篇
尹正杰
|
2月前
|
Go
Golang语言文件操作快速入门篇
这篇文章是关于Go语言文件操作快速入门的教程，涵盖了文件的读取、写入、复制操作以及使用标准库中的ioutil、bufio、os等包进行文件操作的详细案例。
尹正杰
64 4
Golang语言文件操作快速入门篇
尹正杰
|
2月前
|
Go
Golang语言之gRPC程序设计示例
这篇文章是关于Golang语言使用gRPC进行程序设计的详细教程，涵盖了RPC协议的介绍、gRPC环境的搭建、Protocol Buffers的使用、gRPC服务的编写和通信示例。
尹正杰
99 3
Golang语言之gRPC程序设计示例