一场版本升级引发的性能血案的追凶过程
1. 故事的开始
上周 ActFramework 推出 act-1.8.8-RC4 版本 后, 我兴致勃勃更新了 TFB 性能 PK 项目 到最新版, 经过漫长的 60 小时 ( TFB 的一次运行周期是 60 小时) 等待后终于等来了 .............................................. 噩耗: Act 这次的性能骤然下降, 不同测试的下降范围从 60% 到 90% 不等!
不多说了, 说起来都是泪啊. 先上图吧 (为了更加切合重点, 设置了测试过滤, 只显示 Java 全栈框架, 且排除掉了直接用 JDBC 的测试项目):
1.1 JSON 测试
JSON 测试性能下降: 74%
1.2 单次数据库查询测试
单次数据库查询测试性能下降: 73%
1.3 20 次数据库查询测试
20 次数据库更新测试性能下降: 76%
1.4 数据查询带后台模板测试
数据查询带后台模板测试下降: 60%
1.5 20 次数据库更新性能测试
20 次数据库更新测试下降: 50%
1.5 返回 helloworld 字串性能测试
返回 helloworld 字串测试下降: 90%
2. 追凶
这个结果直接把 ActFramework 扔进 Spring 的朋友圈去了, 这分明就是叔叔可以忍, 婶婶不能忍啊. 立马拉响红色警报, 开始缉拿凶手.
2.1 从简单之处入手
既然所有测试结果都有所下降, 那就从最简单的 Hello World 开始调查. 启动项目先:
先看能不能访问, 再拿出 wrk 压测一万年
2.2 被神器忽悠了
现在祭出白试不爽神器 JVisualVM, 开始抽样 CPU
果然发现猫腻, Router.getInvoker 居然吃掉大部分 CPU, 这是種么回事? 创建一个 SNAPSHOT 来分析一把:
WTF! binarySearch 居然会是 bottleneck !!! 我读书虽少也不是随便相信鬼话的人, 不过还是查看一下代码先:
这里面的 targetMethods 是这样的:
并没有一万个东西需要 search 啊, 这个 JDK 的二分查询会是瓶颈, 打死老码农也不会相信啊. 追凶时间迅速从七七四十九分钟上升到了九九八十一分钟, 还是没有任何进展.
2.3 抓住头号凶手
既然头号嫌疑犯搞不清楚, 那就追查二号嫌犯吧. 回到 CPU 抽样, 看到这个 org.osgl.util.S$Buffer.<init> 比较射眼睛:
是什么原因造成 Buffer 分配成为瓶颈的呢? 在创建一个 SNAPSHOT, 暂时掠过一号嫌疑, 从二号入手, 果然发现蹊跷之处:
每个请求进来都会创建 ActionContext, 毫无疑问这是兵家必争之地, 绝对绕不过去的, 跑回去看代码发现 ActionContext 的父类出现了这么一条语句:
的确是在 act-1.8.2 的时候整进去的, 目的是搞这么一个东西, 以后就不需要创建新的 StringBuilder了,可以降低 GC 压力. 可是当时不知道发什么神经, 居然一开始就给 buffer 初始化最大限额的空间, 话说这个默认空间大小是这样设定的:
而中间 calc.calculate 的过程是这样的:
用简单的话来讲就是默认大小是 JVM 可用内存大小的 128 分之一再除以线程数, 这个数字对于 TFB 测试 (给 JVM 分配了 2G) 来讲差不多是 512K. 也就是说每次请求进来先分配几百 k 的空间, 这个当然是不能忍受的. 当时的思路没有问题, 不过残酷的事实再次让老码农复习了 "理想是美好的 现实是骨感的" 这句箴言
立马干掉这个逻辑之后, 果然发现性能提升了至少 50%.
2.4 第二个凶犯暴露
回过头来研究头号嫌犯依旧没有进展, 不过在整个过程中发现了第二个性能损耗的凶手, 在 act-1.8.8 中引入的新式武器, 允许开发人员使用 Query 参数来 overwrite HTTP Header, 比如直接在浏览器上模拟发起 JSON 类型请求可以这样写: GET /url/?act_header_content_type=application%2Fjson&act_header_accept=application%2Fjson 可以让 Act 将该请求的 Content-Type 和 Accept 头当作 application/json 处理. 这个过程需要做 Keyword 匹配, 单次消耗时间虽然可以忽略不及, 但是要上 TFB 这种残酷擂台, 这样的消耗都是不能忽略的. 所以立马发明了一个新的配置 act.header.overwrite, 当设置为 true 的时候上面的特性才会生效. 这样又能提高几个百分点了.
2.5 第三个凶犯
折腾了一整天的 JVisualVM 还是不能搞清楚 Router 里面那个方法的问题. 最后老码农发飙了, 放弃了神器, 经过研究下载了 JProfiler 来帮助搞清楚这个事情. 需要花钱的东西和白给的东西之间的差距不用说了, JProfiler 立马把问题查的清清楚楚:
1.8.1 的情况:
1.8.8-RC4 的情况
非常明显的区别, 在 plaintext 的测试中 1.8.1 走了捷径, 没有调用 before after callback, 也因此没有设置 Content-Type 头, 经过继续追凶, 还发现 1.8.1 没有 clear ActionContext. 这里 1.8.8-RC4 并没有大的问题, 其实是修复了 1.8.1 的逻辑错误. 这部分性能损耗是应该的, 无法避免. 当然老码农也做了一些响应的优化, 比如允许开发人员指定某些请求处理器不参与 before, after 的 event trigger 过程. 这些都是题外话了.
3. 总结
对于 Java 系统遇到性能问题时的应对方式:
- 从简单情况入手
- 学会使用 JVisualVM (JDK 自带, 免费免费免费)
- 当 JVisualVM 开始忽悠的时候要请出真正的高手, 就像 JProfiler 这样的.
4. 题外话
TFB (TechEmpower Framework Benchmark) 平台不仅仅是一个展示框架实力的 T 型台, 更重要的是能够帮助框架作者发现自己框架一些潜在的问题, 是一个极好的测试反馈工具. 对于框架用户来讲则是提供了一个相对客观的参考, 不仅框架性能可以通过 TFB 直接拿到 , 框架的易用性也可以通过参加框架的测试项目反映出来.
目前在国内已经有多个开源产品登陆 TFB, 包括 Java 阵营的 ActFramework, blade 和 redkale; Go 阵营的 beego, revel; D 语言阵营的 hunt 还有宇宙语言 PHP 阵营中的 swoole 最近也加入了 TFB, 而且表现出非常强劲的实力, 值得围观