go pprof 性能分析

写了一些代码,但是不知道性能是什么?怎么样?go提供了go test 和go tool 原生工具对go性能进行评估 ,本文尝试使用传说中的PProf分析下性能:

PProf包

net/http/pprof :采集程序(非 Server)的运行数据进行分析
runtime/pprof:采集 HTTP Server 的运行时数据进行分析

#其实net/http/pprof中只是使用runtime/pprof包来进行封装了一下,并在http端口上暴露出来
#服务进程
#我的go程序是用http包启动的web服务器,引入_ "net/http/pprof"包,在浏览器中使用[http://localhost:port/debug/pprof/](http://localhost:port/debug/pprof/)直接看到当前web服务的状态,包括CPU占用情况和内存使用
import (
    "log"
    "net/http"
)

func main() {
    go func() {
        log.Println(http.ListenAndServe(":8888", nil))
    }()

    //  其它
}

#应用程序
#pprof.StartCPUProfile和pprof.StopCPUProfile 分析内存情况
import (
    "flag"
    "log"
    "os"
    "runtime/pprof"
    "testing"
)

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
func Benchmark_PProf(b *testing.B) {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal(err)
        }
        err = pprof.StartCPUProfile(f)
        if err != nil {
            panic("StartCPUProfile err")
        }
        defer pprof.StopCPUProfile()
    }
}
运行程序的时候加一个--cpuprofile参数,比如fabonacci --cpuprofile=fabonacci.prof
这样程序运行的时候的cpu信息就会记录到XXX.prof中了。

首先 PProf可以做什么?

CPU profiling cpu分析,按照一定的频率100Hz(10ms)采集所监听的应用程序cpu(含寄存器)的使用情况,确定应用程序在主动消耗cpu周期时花费时间的位置
Memory Profiling 内存分析,在应用程序进行堆分配记录堆栈跟踪,用于监听当前和历史内存使用情况,以及检查内存泄漏。
Block Profiling 阻塞分析,记录goroutine 阻塞等待同步(包含定时器通道)的位置,默认不开启,需要调用 runtime.SetBlockProfileRate 进行设置
Mutex Profiling 互斥锁分析。报告互斥锁的竞争情况,默认不开启,需要调用 runtime.SetMutexProfileFraction 进行设置

我的是一个服务进程

#直接访问网页:
profile(CPU Profiling): $HOST/debug/pprof/profile,默认进行 30s 的 CPU Profiling,得到一个分析用的 profile 文件
allocs 查看过去所有内存分配样本,访问路径为 /debug/pprof/allocs
cmdline 当前程序命令行的完整调用路径
block(Block Profiling):$HOST/debug/pprof/block,查看导致阻塞同步的堆栈跟踪
goroutine:$HOST/debug/pprof/goroutine,查看当前所有运行的 goroutines 堆栈跟踪
heap(Memory Profiling): $HOST/debug/pprof/heap,查看活动对象的内存分配情况
mutex(Mutex Profiling):$HOST/debug/pprof/mutex,查看导致互斥锁的竞争持有者的堆栈跟踪
threadcreate:$HOST/debug/pprof/threadcreate,查看创建新OS线程的堆栈跟踪
一般在线上环境,为了网络安全,通常不会这么做。另外debug的访问方式是具有时效性的,在实际场景中,我们常常需要及时将当前状态下的 profile文件给存储下来,便于二次分析。
#通过终端访问
//在执行命令后,需要等待 60s (可以调整seconds的值) PProf 会进行 cpu Profiling , 结束后将默认进入PProf 的命令行交互模式,查看或者导出分析结果。
// 如果是以TLS方式启动的HTTP Server 那么在调用需要改成 go tool pprof https+insecure://localhost:6060/debug/pprof/profile?seconds=60
默认进入30秒的profile收集时间,每100Hz(10ms)采样一次,seconds修改采样时间为60S
go tool pprof http://localhost:8080/debug/pprof/profile?seconds=60
Saved profile in C:\Users\Administrator\pprof\pprof.samples.cpu.005.pb.gz
Type: cpu
Time: Aug 30, 2021 at 5:00pm (CST)
Duration: 30s, Total samples = 1.97s ( 6.57%)
Entering interactive mode (type "help" for commands, "o" for options)

//命令能够很快的拉取到结果。不需要采样等待, 需要注意的是 Type 这个选项默认是 inuse_space,实际上,它可以对多种内存情况进行分析
#inuse_space 分析应用常驻内存的占用情况
go tool pprof  http://10.254.0.193:60007/debug/pprof/heap
heap堆分配采样
Saved profile in C:\Users\Administrator\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.006.pb.gz
Type: inuse_space
Time: Aug 30, 2021 at 3:43pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)

(pprof) top 10
       flat  flat%   sum%        cum   cum%
     370ms 18.78% 18.78%      370ms 18.78%  runtime.stdcall1


flat:当前函数上运行耗时
flat%:函数自身占用的 CPU 运行耗时总比例
sum%:函数自身累积使用 CPU 总比例
cum:当前函数及其调用函数的运行总耗时
cum%:函数自身及其调用函数占 CPU 运行耗时总比例
最后一列为函数名称

#alloc_objects 分析应用程序的内存临时分配情况
go tool pprof  -alloc_objects http://localhost:8080/debug/pprof/heap
Saved profile in C:\Users\Administrator\pprof\pprof.samples.cpu.006.pb.gz

#另外还有 inuse_objects 和 alloc_space 类别,分别对应查看每个函数的对象数量和分配的内存空间大小。
go tool pprof   http://localhost:6060/debug/pprof/goroutine
Saved profile in C:\Users\Administrator\pprof\pprof.goroutine.001.pb.gz
Type: goroutine
Time: Aug 30, 2021 at 5:10pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)traces
Type: goroutine
Time: Aug 30, 2021 at 5:10pm (CST)
-----------+-------------------------------------------------------
        12   runtime.gopark
             runtime.chanrecv
             runtime.chanrecv2
             github.com/klauspost/compress/zstd.(*blockDec).startDecoder

#在查看goroutine 时可以使用traces命令,这个命令会打印出对应的所有调用栈,以及指标信息,通过这个命令我们可以很方便的查看整改调用链路有什么,分别在哪里使用了多岁个goroutine,并且通过分析可以知道谁才是真正的调用方,输出结果如下:
E:\Go\src\sevennine.coding.net\ProjectCode\GameServer>go tool pprof  http://10.254.0.193:60007/debug/pprof/heap
Fetching profile over HTTP from http://10.254.0.193:60007/debug/pprof/heap
Saved profile in C:\Users\Administrator\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.007.pb.gz
Type: inuse_space
Time: Aug 30, 2021 at 5:15pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) traces
Type: inuse_space
Time: Aug 30, 2021 at 5:15pm (CST)
-----------+-------------------------------------------------------
     bytes:  48B
         0   reflect.unsafe_NewArray
             reflect.MakeSlice
             encoding/asn1.parseSequenceOf
             encoding/asn1.parseField
             encoding/asn1.parseSequenceOf
             encoding/asn1.parseField
             encoding/asn1.UnmarshalWithParams
             encoding/asn1.Unmarshal
             crypto/x509.parseCertificate
             crypto/x509.ParseCertificate
             crypto/x509.extractSimpleChain
             crypto/x509.(*Certificate).systemVerify
             crypto/x509.(*Certificate).Verify
             crypto/tls.(*Conn).verifyServerCertificate
             crypto/tls.(*clientHandshakeState).doFullHandshake
             crypto/tls.(*clientHandshakeState).handshake

#在调用 chan (通道)、sync.Mutex (同步锁)或者 time.Sleep() 时会造成阻塞

#需要特别注意的是 runtime.SetMutexProfileFraction(1) 语句,如果未来希望对互斥锁进行采集,则需要调用该方法设置采集频率,如果没有设置,或者设置数值小于0,则不进行采集
func init() {
   runtime.SetMutexProfileFraction(1)
}

#接下里调用 go tool pprof 进行分析:
go tool pprof   http://localhost:6060/debug/pprof/mutex
Saved profile in C:\Users\Administrator\pprof\pprof.contentions.delay.001.pb.gz
Type: delay
Time: Aug 30, 2021 at 5:20pm (CST)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)top
Showing top 10 nodes out of 26
      flat  flat%   sum%        cum   cum%
   29.38us   100%   100%    29.38us   100%  sync.(*Mutex).Unlock
         0     0%   100%     4.62us 15.72%  database/sql.(*Rows).Close
         0     0%   100%     4.62us 15.72%  database/sql.(*Rows).Next

#调用 list命令 查看指定函数的代码情况 (包含特定的指标信息,如耗时)若函数名不明确,则默认对该函数名进行模糊匹配:
#从输出分析中可以看到引起互斥锁函数,以及锁开销的位置。

# 与 Mutex 的 runtime.SetMutexProfileFraction 语句类似,Block也需要调用 runtime.SetBlockProfileRate 语句进行设置,如果没有设置,或者设置数值小于0,则不进行采集
func init() {
   runtime.SetMutexProfileFraction(1)
   runtime.SetBlockProfileRate(1)
}

go tool pprof   http://localhost:6060/debug/pprof/block
Saved profile in C:\Users\admin\pprof\pprof.contentions.delay.004.pb.gz
Type: delay
Time: Oct 13, 2020 at 12:35am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 83.75us, 100% of 83.75us total
      flat  flat%   sum%        cum   cum%
   83.75us   100%   100%    83.75us   100%  sync.(*Cond).Wait
(pprof)

# 也可以用 list 命令查看具体阻塞情况。调用方式和 Mutex Profiling 一样

image.png

参考:https://www.cnblogs.com/gwyy/p/13807267.html

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,752评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,100评论 3 387
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 159,244评论 0 349
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,099评论 1 286
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,210评论 6 385
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,307评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,346评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,133评论 0 269
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,546评论 1 306
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,849评论 2 328
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,019评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,702评论 4 337
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,331评论 3 319
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,030评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,260评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,871评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,898评论 2 351

推荐阅读更多精彩内容