NodeJS性能调优之GC调优

背景

近期,为了评估服务性能,测试同学对关键业务接口进行了压测,单台NodeJS服务开启3个进程的情况下,QPS最高达320多。为了确认服务是否还有优化空间,我们使用阿里云的 NodeJS性能平台 对服务进行分析,定位了服务的瓶颈,并在阿里云的同学帮助下采取了相应的措施,优化了服务的性能。

问题排查与分析

Step1 获取与分析CPU Profile

当我们以400并发量,对单一业务接口进行压测,发现QPS为320时,服务器CPU被打满。为了找到是什么原因导致CPU达到了性能瓶颈,我们使用了阿里云的「NodeJS性能平台」,抓取了压测时的 CPU Profile 信息。

CPU Profile

经过分析,我们发现 _tickDomainCallbackgarbage collector 在CPU占比很大,其中 _tickDomainCallback占了50%多,GC 也占了27%的比例。通过展开 _tickDomainCallback 里的内容,发现CPU占比高的逻辑主要是TypeORM 和4处业务逻辑。

_tickDomainCallback 展开信息

Step2 排查数据库性能

当我们看到TypeORM时,我们以为是数据库消费不过来(生产与消费能力不匹配,Query队列产生大量堆积),导致TypeORM消耗大量CPU资源。后来,我们进行了第二次压测,并在服务器CPU打满时获取了RDS的性能分析报告。报告显示:

  • 数据库CPU使用了15%的资源
  • 平均查询响应速度小于15ms
  • 无慢查询记录
  • 无死锁记录

因此,我们排除了RDS导致TypeORM消耗CPU资源。我们推测可能与TypeORM本身的代码有关,我们使用了一个非常早期的TypeORM版本(v0.0.11)。阿里云的同学推荐我们升级TypeORM的版本试试,看看会不会有所改善。但是最新的TypeORM版本与早期的版本API已经发生了变化,无法进行平滑升级。因此,放弃了对TypeORM优化。

Step3 排查业务逻辑代码

我们将可能影响性能的业务代码进行了Review,发现优化空间并不是很大,代码本身已经经过了精简和优化。无法进行进一步提升,我们将优化重点放在了占比高达27%的 GC 上。

Step4 GC 信息抓取与分析

为了获得详细的GC信息,我们再次进行了压测,并获取了 GC Trace 信息。结果如下图:

GC Trace

从图中,我们可以获取到一些重要信息:

  • GC时间占比为26.87%
  • 3分钟内,GC暂时时间为47.8s,且scavenge占了大多数
  • 平均GC暂停时间为50~60ms

根据这些信息,我们可以得出 scavenge 非常频繁,导致了CPU资源的占用。
scavenge 发生在新生代的内存回收阶段,这个阶段触发条件是, semi space allocation failed(半空间分配失败)。可以推测出,压测期间我们的代码逻辑频繁的生成大量的小对象,导致 semi space很快被分配满,从而导致了 scavenge 回收和CPU资源的占用。既然这样,我们可不可通过调整 semi space(半空间)的大小,减少GC的次数来优化对CPU的占用。

Step5 GC 调优与测试

NodeJS在64位系统上,默认的semi space大小为16M。

我们将 semi space 进行了3次调整,分别设为64M、128M、256M,对不同值情况下的服务进行了压测并获取了对应 GC TraceCPU Profile

修改 semi space 方法

对于普通node服务:

node index.js --max_semi_space_size=64

对于PM2启动的服务,在pm2的config文件中添加:

node_args: '--max_semi_space_size=64',

1) 64M

semi space 修改为64M,并进行线上压测,获取压测时的 GC TraceCPU Profile信息:

GC Profile信息

CPU Profile

对比修改前的数据,我们发现:

  • GC的CPU占比从27.5%下降到了7.14%;
  • 3分钟内GC次数,从1008次降到了312次。其中,Scavenge的次数从988次下降到了294次;
  • GC时间,从原来的47.7s下降到了11.8s
  • GC平均暂停时间在40ms左右

GC时间从47.7s下降到了11.8s,相应的,QPS提升了10%。

2) 128M

semi space 调整到128M,得到的 GC TraceCPU Profile信息:

GC Trace

CPU Profile

对比64M时的数据,我们可以发现:

  • 与64M时GC次相比,GC次数从312下降到了145;
  • Scavenge算法回收时间,增加了1倍。从平均50ms涨到了100ms;
  • Mark-sweep的次数没有发生变化
  • CPU占比略微下降,从7.14降到了6.71

可以看出,将 semi space从64M调整到了128M,性能并没有很大的提升。相反,Scavenge算法回收时间几乎增长了一倍。

3) 256M

semi space 调整到256M,得到的 GC TraceCPU Profile信息:

GC Trace

CPU Profile

可以观察到:

  • 与128M时相比,GC次数下降了一倍
  • 但是Scavenge回收的时间,波动到了150ms。
  • CPU占比,也略微下降了一点,降到了5.99

可以看出,将 semi space调整到了 256M,性能并没有显著提升,且增加了 Scavenge 的回收时间。

小结

semi space 从16M调整到64M时,GC的CPU占比从27.5%下降到了7.14%,Scavenge算法平均回收耗时减少,QPS提升了10%。继续调大 semi space,性能并没有显著提升,且Scavenge算法回收时间增加。semi space本身用于新生代对象快速分配,不适合调整过大。因此,semi space 设置为64M较为合适。

总结

通过将semi space调大,触发 Scavenge算法回收的概率降低,GC的次数也随之减少。且 Scavenge算法回收内存的时间也较为合理,因而可以降低GC在CPU中的占比。

本文主要介绍了线上服务的性能瓶颈的排查与GC调优,并没有介绍V8 垃圾回收机制的原理。推荐感兴趣的同学,阅读朴灵老师的《深入浅出Node.js》中关于《V8的垃圾回收机制》一节。其中,详细了介绍了V8用到的各种算法,非常有助于理解性能调优的原理。

最后,感谢一下阿里的奕钧同学,在他的帮助下,帮我解决了问题。

参考资料

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

推荐阅读更多精彩内容