go pprof与线上事故:一次成功的定位与失败的复现

背景:一次大几万人的线上抢购活动,突然出现了问题,页面半天打不开,打开了半天下不了单,cpu涨了又跌跌了又涨,而内存使用又稳如老狗!不要慌,按照套路去分析问题,一切都不是问题!

阅读此文你将收获:

  • 分析问题的一个思路!
  • 学会使用pprof定位问题。
  • 解决问题的一个思路!
大纲:
  1. 我是如何定位问题的
  2. 如何通过pprof精准定位
  3. 通过pprof来定位代码
  4. 我是如何trouble shooting

一. 我是如何思考问题的

“活动挂了,下不了单!”,随着一声凄凉的惨叫,办公室大门被运营人员打开,于是活动团队开始了紧张的bug定位过程。通过一段时间的代码查看未能定位问题,重启也没法解决。

通过finalshell上的机器使用率显示,我们发现了一个有趣的现象,CPU的使用率从30%涨到60%再涨到99%,然后又从10%开始一路往上涨,如此往复,但是内存的使用率却一动不动,非常稳定。

为什么CPU会暴涨

CPU为什么这么奇怪?CPU是干什么的?
CPU是负责计算的!

那么我们来猜测一下导致CPU暴涨的原因:

  1. 是某段代码涉及计算量过大?
  2. 是小对象太多?导致GC压力过大?

然后导致cpu资源占用过高,在高并发环境下请求积压越来越多?处理不了?

有了初步推测,下一步就该用出golang性能分析大杀器---pprof

二. 如何用pproof精准定位

很多小伙伴担心线上使用pprof会影响性能,担心安全问题。这个在我看来利大于弊,当服务出现问题的时候,资源占用多一点点与能够解决问题相比微不足道,当服务没有问题的时候使用pprof那更没有问题了~

在这里要推荐来自鹅厂大佬陈一枭在深圳gopher meetup上的分享:

《Go性能优化之路》有详细的PDF告诉你pprof以及性能优化的各种细节,更有教程demo让你参考!
重点如下:
基准---benchmark的使用
分析工具:GODEBUG
分析工具:go tool pprof
分析工具:go tool trace
PS:已经与鸟哥沟通过,获得使用许可

2.1 CPU Profile的使用

先期准备:几行代码导入pprof

package main

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

func main() {
    // 服务端启动一个协程,支持pprof的handler
    //导入pprof的包,自动包含一些handler
    //项目加入如下代码
    go func() {
        http.ListenAndServe("0.0.0.0:8888", nil)
    }()
    //other code
}
1.先看Graph图

点击view,选中graph

该图展示了函数逻辑调用树,框越红,越大表示消耗越多!

直接将图缩到最小

在该步骤中,我们直接将graph图缩到整个屏幕可见,哪里红线明显,哪里框框最大,一目了然

通过缩略图我们标记了四个消耗量大的点位。我们再继续看放大图。

标记点1
标记2和标记3
标记4
选择sample采样
2.再看flame图
flame图SAMPLE中的cpu
  • 火焰图中的X轴表示CPU耗时,越宽占用时间越多
  • Y轴表示函数栈调用深度,尖刺越高表示函数栈调用越深

flame选中samples

我们可以看到其实采样SAMPLE中选择cpu或者samples都差不多,消耗越大的地方CPU占用越高,采样点也是越集中在这里!

3.再看Top
VIEW中选择Top
  • Flat:函数自身运行耗时
  • Flat%:函数自身耗时比例
  • Sum%:指的就是每一行的flat%与上面所有行的flat%总和
  • Cum:当前函数加上它之上的调用运行总耗时
  • Cum%:当前函数加上它之上的调用运行总耗时比例

举例说明:函数b由三部分组成:调用函数c、自己直接处理一些事情、调用函数d,其中调用函数c耗时1秒,自己直接处理事情耗时3秒,调用函数d耗时2秒,那么函数bflat耗时就是3秒,cum耗时就是6秒。

// 该示例在文末参考列表的博客中
func b() {
    c() // takes 1s
    do something directly // takes 3s
    d() // takes 2s
}
4.看看内存Profile
Graph_inuse_object
  • alloc_objects:收集自程序启动以来,累计的分配对象数
  • alloc_space:收集自程序启动以来,累计的分配空间
  • inuse_objects:收集实时的正在使用的分配对象数
  • inuse_space:收集实时的正在使用的分配空间

如图显示这两个地方使用对象最多,分别占比53.10%与26.63%,二者相加等于79.73%。
GC收集的就是内存中的小对象,而这里我们所见的UnmarshalJSONjson compact所产生的对象占了80%,这里可以列入优化点!

三.通过pprof的定位来追代码

通过pprofCPU与内存的GraphFlame GraphTop,我们基本清楚了程序性能消耗大户就在json.Unmarshal这一块。下面我们通过针对第一个标记点的分析,来示例如何查找问题代码的。

问题代码函数调用链

从上图可以分析出来是api.GetGiftCategoryDetails这个方法消耗了太多性能,因为往下走就是redisHGetObjectjson的Unmarshal方法,这些方法属于不可控方法,不能直接对其进行修改,所以定位就定位在api.GetGiftCategoryDetails这个方法上!

func GetGiftCategoryDetails
上图为pprof中标记1的主要方法,pprof cpu显示,该方法消耗了大量的CPU时间。
该方法被调用的时候会判断in.Giftcategoryid是否有值,有值则从redis中取出数据。
进入HGetObject方法,如下图:

HGetObject

继续进入decode方法!

decode

在该方法中我们看到了p.Option.Unmarshal,这个跟我们在pprof中看到的json Unmarshal是什么关系呢?
进入p.Option.Unmarshal中查看。

Unmarshal

到这里就明白了默认使用的是json.Unmarshal反序列化方法

那么我们从pprof中所观察到的一切都能够串联起来了,整个逻辑流程如下:

调用流程

文章看到这里,在回头看看pprofCPU还有其他的各种截图,结合代码,整个流程清晰明了,就是从redis中取出数据的时候进行的json.Unmarshal损耗CPU性能太多!

四. 我是如何trouble shooting的

既然我们知道了是json反序列化的问题导致这次线上事故的产生,那么这个问题我们该如何解决呢?


小case

这个很容易想到,既然标准库中的json序列化效率不高,咱们换个高效率的不就行了吗?例如:https://github.com/json-iterator/go

但是,换了高效的json反序列化包,那么效率到底能够提升多少呢?30%?50%,100%,三倍?五倍?十倍?···

我的看法是:脱离业务谈技术的都是耍流氓!

事情并不简单

在不清楚业务的情况下,任何解决方案都只是猜测而已,因为最高效的手段永远都是从业务上去解决,然后再是技术手段。

通过与活动团队沟通,了解到业务逻辑如下:

  1. 近百万用户分为三个类别。
  2. 每个类别用户进入都会取出不同的商品列表。
  3. 商品列表存redis中。
  4. 每次从redis中取下来后反序列化返回给用户端。

那么看完了整个业务流程,应该怎么去做呢?
咱们不妨从下面两个角度想一想:

  • 技术角度(换json包)
  • 业务角度(利用本地缓存)

几万个用户几乎同时取redis中取三种相同的臃肿的数据,然后还需要经过json反序列化去消耗大量的CPU,这样做是否合理?

如果你觉得这样不合理,那咱们换一个思路:
如果我们将这三类商品列表放在全局变量中,每次来了直接从全局变量中获取这个方法怎么样?(最简单的一种办法,也可以使用多级存缓,具体根据团队情况取舍,例如考虑一下代码复杂度是否增加)

来,咱们算一算两种方式的开销如何:
1.redis走网络开销至少ms级,走内存ns级,这里省了有没有一万或者八千倍

  1. 从内存中取数据,避免每次方法调用后对临时变量的销毁,还记得pprof标记点4吗?间接解决了GC压力的问题
  2. 不需要经过json序列化···掐指一算,省了···(不好意思,程序就卡死在这里,这里还有算的必要吗?)

我们反思复盘一下,要是我们不考虑业务直接换json库换上目前性能最高的json库,那么下次活动结果会如何?(心里知道就行了)

总结:

1.谈一谈基础

起码得知道CPU是计算资源,查看CPU使用率和负载,当CPU使用率低,负载高是个什么情况。

又例如服务OOM了得考虑是不是内存泄漏了,当内存泄漏的时候,操作系统杀的一般是占用内存最大的而不是泄露的···

2.了解分析工具的使用

常用的性能分析工具要掌握,pprof肯定不用说,还有一些Linux命令例如topuptime,还有查看TCP连接数的等等命令。

3.该如何解决问题

首先得分析问题,是CPU问题还是内存问题,又或者是网络问题。当三者都没问题的时候,请你压一压是不是自己程序性能有问题···

当能够充分定位问题的时候,首先得梳理清楚业务流程,因为一般我们用的包或者标准库,亦或是框架,他们的性能相差其实也没有大到很离谱,除非你故意挑个玩具代码来应用到生产环境。

先确认业务流程和程序处理上已经没有优化的空间,请再考虑寻找一个高效的库,或者自己去实现一些代码优化措施!

PS:该业务不是我负责的,纯属同事之间友情互助,帮忙查找问题。至于后来我也模拟过同样的数据,利用time.sleep(5ms)模拟从redis取数据的开销,然后反序列化,但是并未出现CPU使用率波浪式呈现。太遗憾了,要是有知道的大佬还望不吝赐教!

感谢 阿郎,孙伟,陈一枭等大佬提供的帮助
孙伟的GitHub:https://github.com/xiaowei520

参考资料与推荐阅读文章:
滴滴实战分享:通过 profiling 定位 golang 性能问题 - 内存篇
Go语言性能优化工具pprof文本输出的含义
linux下查看cpu负载及分析

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