文档章节

一场版本升级引发的性能血案 - 之数据历险

罗格林
 罗格林
发布于 2018/05/30 10:20
字数 2263
阅读 765
收藏 7

1. 案情回顾

老码农在 一场版本升级引发的性能血案的追凶过程 中谈到了 ActFramework 在 TFB 第 N 轮内部测试中全线溃败落入 Spring 朋友圈的不堪回首之往事. 历经三天两夜追凶过程, 老码农终于定位到了一 ActContextBase.<init> 中以 500K 字节初始化 S.Buffer 为首的犯罪集团, 并提交了新的 PR, 最新的内部测试结果已经收到果然让 Act .................................................... 某些部分重回性能巅峰. 还是上图先:

1.1 JSON 测试结果比较

TFB JSON - act-1.8.2

image

TFB JSON - act-1.8.8-RC6

image

1.2 单次查询测试结果比较

TFB Single Query - act-1.8.2

image

TFB Single Query - act-1.8.8-RC6

image

1.3 多次查询测试结果比较

TFB Multiple Queries - act-1.8.2

image

TFB Multiple Queries - act-1.8.8-RC6

image

1.4 数据 + 后台模板测试结果比较

TFB Fortunes - act-1.8.2

image

TFB Fortunes - act-1.8.8-RC6

image

1.5 多次数据更新测试结果比较

TFB Updates - act-1.8.2

image

TFB Updates - act-1.8.2

image

1.6 静态字串返回测试结果比较

TFB Plaintext - act-1.8.2

image

TFB Plaintext - act-1.8.8-RC6

image

数据不会说谎, 可以看出老码农的努力让 ActFramework 在 JSON/Plaintext 两项测试中重回性能王座. 但是 SQL 数据库的各项测试还是全线溃败, 这有点令老码农干瞪眼儿了. 不过老码农是那种轻言放弃的人么. 啥也不说了, 挽起袖子开始撸吧.

2. 数据历险

从上次的教训中我们已经知道了 JProfiler 是一个更好的性能检测工具. 所以我们还是继续依赖 JProfiler 为我们提供分析数据.

2.1 获得历史对照数据

先找出最近一次没有性能降级问题的 SNAPSHOT, 感谢 TechEmpower 为我们提供的 tfb-status 报告, 我们很容易找到最近一次没有出现问题的版本为 88180d6d3e3aded7682c653f3f7766b578b16835. 运行下面的命令检出该版本:

luog@luog-X510UQR:~/p/TEB$ git co -b 1.8.1 88180d6d3e3aded7682c653f3f7766b578b16835 
Switched to a new branch '1.8.1'

ActFramework 为 TFB 数据访问测试提供了多项组合, 包括:

  • ebean + mysql
  • ebean + postgresql
  • hibernate + mysql
  • hibernate + postgresql
  • eclipselink + mysql
  • eclipselink + postgresql

这些组合的测试成绩同步下降, 有充分理由相信他们都是有相似的原因引起的. 老码农选择了 eclipselink + mysql 组合来分析性能下降的原因, 主要原因是 eclipselink 是标准的 JPA 实现, 而且比 hibernate 要简单一下(只是比 hibernate 简单一点点, 后来的经历让老码农充分了解了数据库访问的复杂程度).

下面我们就按照该组合来 build 运行版本, 并启动应用:

luog@luog-X510UQR:~/p/TEB/frameworks/Java/act$ mvn -q -P eclipselink_mysql clean package
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act$ cd target/dist
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act/target/dist$ unzip actframework-1.8.1-r88180d.zip
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act/target/dist$ ./run -p eclipselink_mysql
Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=128M; support was removed in 8.0
        _  ___   _   _                _           _    _      
  /\   /    |   |_  |_)   /\   |\/|  |_  \    /  / \  |_)  |/ 
 /--\  \_   |   |   | \  /--\  |  |  |_   \/\/   \_/  | \  |\ 
                                                              
                          powered by ActFramework r1.8.1-6fcc0

 version: r1.8.1-88180d
scan pkg: com.techempower.act
base dir: /home/luog/p/TEB/frameworks/Java/act/target/dist
     pid: 25323
 profile: eclipselink_mysql
    mode: PROD

     zen: There should be one-- and preferably only one --obvious way to do it.
          Although that way may not be obvious at first unless you're Dutch.

下面就先用 wrk 生成两次 15s 的压测请求, 预热 JVM

luog@luog-X510UQR:~$ wrk -t4 -c128 -d15s http://localhost:5460/db
Running 15s test @ http://localhost:5460/db
  4 threads and 128 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    16.36ms   27.94ms 342.41ms   91.27%
    Req/Sec     3.54k     1.85k    9.32k    58.60%
  203184 requests in 15.09s, 36.00MB read
Requests/sec:  13462.55
Transfer/sec:      2.39MB
luog@luog-X510UQR:~$ wrk -t4 -c128 -d15s http://localhost:5460/db
Running 15s test @ http://localhost:5460/db
  4 threads and 128 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    10.32ms   16.61ms 216.92ms   91.24%
    Req/Sec     5.11k     1.91k   18.69k    81.13%
  302010 requests in 15.08s, 53.51MB read
Requests/sec:  20029.88
Transfer/sec:      3.55MB

接下来就是启动 JProfiler 连接刚刚启动的进程:

image

JProfiler 在启动的时候会询问是否 instrument 还是 sample. 这里我们选择 instrument, 因为需要监测的部分我们是很清楚的

image

需要注意的是 Filter 的定义对于 instrument 非常重要. 我们在这里选择对这个测试更加重要的类, 简单地说就是和数据库访问相关的类:

image

在上面的对话框中我们选择了一下 package:

  • act.db
  • javax.persistent
  • org.eclipse.persistent
  • osgl.util
  • com.mysql
  • com.zaxxer.hikari

一共有超过 4000 个类, 其中绝大部分都是 eclipselink 的.

同时我们也打开数据库 probe 设置:

image

JProfiler 开始之后运行 wrk 来生成压测请求 30 秒:

luog@luog-X510UQR:~$ wrk -t4 -c128 -d30s http://localhost:5460/db

下面就是 JProfiler 捕获到的数据:

image

我们先保存为 SNAPSHOT, 等收集到有问题版本的数据之后对二者做对比.

2.2 获得最新数据

还是通过 tfb-status 拿到最近的版本, checkout 出来运行:

luog@luog-X510UQR:~/p/TEB/frameworks/Java/act$ git co -b RC6 aa59d4e36a24d88f7bd09f1798793893c246e477 
Switched to a new branch 'RC6'
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act$ rm -rf target
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act$ mvn package -q -P eclipselink_mysql
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act$ cd target/dist/
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act/target/dist$ tar xzf teb-act-eclipselink-mysql.tar.gz 
luog@luog-X510UQR:~/p/TEB/frameworks/Java/act/target/dist$ !.
./run -p eclipselink_mysql
Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=128M; support was removed in 8.0
        _  ___   _   _                _           _    _      
  /\   /    |   |_  |_)   /\   |\/|  |_  \    /  / \  |_)  |/ 
 /--\  \_   |   |   | \  /--\  |  |  |_   \/\/   \_/  | \  |\ 
                                                              
                       powered by ActFramework r1.8.8-RC6-c480

 version: r1.8.8.2-aa59d
scan pkg: 
base dir: /home/luog/p/TEB/frameworks/Java/act/target/dist
     pid: 23873
 profile: eclipselink_mysql
    mode: PROD

     zen: Complex is better than complicated.

按照先前的方式先压测两次 15s 预热 JVM:

luog@luog-X510UQR:~$ wrk -t4 -c128 -d15s http://localhost:5460/db
Running 15s test @ http://localhost:5460/db
  4 threads and 128 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    10.52ms   21.48ms 325.82ms   95.75%
    Req/Sec     4.29k     2.18k   12.72k    75.00%
  252609 requests in 15.08s, 36.57MB read
Requests/sec:  16746.37
Transfer/sec:      2.42MB
luog@luog-X510UQR:~$ wrk -t4 -c128 -d15s http://localhost:5460/db
Running 15s test @ http://localhost:5460/db
  4 threads and 128 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.98ms    9.50ms 123.31ms   86.39%
    Req/Sec     5.33k     2.11k   14.22k    82.67%
  319193 requests in 15.06s, 46.20MB read
Requests/sec:  21188.63
Transfer/sec:      3.07MB

JProfiler 也是按照先前的方式连接上面的进程, 开始监测. 同时跑 wrk 生成压测请求 30 秒, 结果如下:

image

下面对两次测试的 CPU Hot Spots 做比较:

1.8.1 (Good one)

image

1.8.8-RC6 (Bad one)

image

看不出什么东西, 对吧. 看不出就对了, 因为老码农也是一脸懵比. 不过发现一个现象, 两个 Session 都有很多方法, invocation 次数超级多, 但是 self 时间非常短:

image

也许把这些方法过滤掉会有一些发现. 说干就干, 重新起一个 JProfiler Session, 把上面那些方法都加到 Session Setting 的 Ignore Methods 当中: image

搞定这些设置之后从头再撸一遍, 情况是这样的:

1.8.1

image

1.8.8-RC6

image

还是不清楚为啥 RC6 比 1.8.1 速度降低了很多, 也许是老码农的 8550U 的机器不够强劲, 反映不出问题吧. 不过还是让老码农逮到一个比较有趣的地方, 两个 session 都有超过 20K 的 com.mysql.jdbc.connectionImpl.prepareStatement 的调用. 这个让老码农很奇怪, PreparedStatement 不应该是重复利用吗?

老码农决定试试 JProfiler 的 Sampling 方式, 又重头开始撸 (这种撸法简直是要人命的节奏啊). 最后得出的情况是:

1.8.1

image

1.8.8-RC6

image

貌似更加清晰一点, 但依然看不出性能下降的原因. 但还是有收获的, 这个 readonly 的请求怎么会在有 ConnectionImpl.rollback 的情况. 结合上次发现的 prepareStatement 调用, 不需要问元芳, 老码农就能断定此中必有蹊跷. 本来以为可以停歇了, 没想到采坑的旅程才刚刚开始. 为了不耽搁大家阅读时间, 就直接看结局吧

3. 结局

老码农第一个深入研究的问题: 为啥 Connection 会 rollback, 这与 prepareStatement 不停调用有何关联, 结果是给 Eclipselink 项目提了一个 Issue 报告, 具体内容也是 TLDR, 欲知详情, 移步这里: https://github.com/eclipse-ee4j/eclipselink/issues/107

那 rollback 的问题来自于 act db 总是建立事务, 对于只读的请求最后调用事务的 rollback, 这个额外开销不能接受, 经过三天两夜连续撸? (噢, 说错了, 是撸码), act 现在可以在数据源配置上只读数据源了, 对于 TFB 项目, 现在的配置是这样的:

db.username=benchmarkdbuser
db.password=benchmarkdbpass
db.isolationLevel=1
db.maxConnections=128
db.minConnections=64
db.slave.maxConnections=256
db.slave.minConnections=128
db.poolServerPrepStmts=true
...

看到其中的 db.slave 了吗? 那就是为只读操作准备的, 只读数据源没有特殊设定的都继承主数据源设定. 看官一定会问, 怎么才能知道应该使用只读而不是主数据源, 这个问题的答案是分两种情况:

  1. 用户显式制定事务类型, 例如:
@Transaction(readonly=true) // specify the transaction is readonly
@GetAction("/db")
public World singleQuery() {...}
  1. 如果用户没有指定事务, 则系统从 Dao 操作来判断, 对于 select, count 等操作, 都不启动事务, 对于 save, update, delete 等操作则判断是否存在事务, 如果没有, 则启动读写事务.

这次的数据历险触发整个 act-sql-common 包括 ebean 和 JPA 的架构完全重写, 而且让老码农采坑无数, 差点就精尽人亡, 不过结果 .................................... 结果老码农也不知道啊, 已经升级了 TFB 项目, 提交了 PR, 需要再等差不多 100 个小时之后就能见分晓了, 希望能给有个惊喜.

咱们下回分解

© 著作权归作者所有

罗格林

罗格林

粉丝 299
博文 45
码字总数 49205
作品 4
其他
架构师
私信 提问
加载中

评论(9)

罗格林
罗格林 博主

引用来自“李文良”的评论

loc是什么工具??给个官网
https://github.com/cgag/loc
李文良
李文良
loc是什么工具??给个官网
sprouting
sprouting
一脸懵逼进来,一脸懵逼出去
拼命奋斗
O(∩_∩)O哈哈~
法球特效
好神奇。。。
法球特效
好神奇。。。
Artlongs
Artlongs
认真撸多点,越撸越带劲。。。
紫电清霜
紫电清霜
看得我快快精尽人亡了
osc前美工
osc前美工
看着一头雾水
一场版本升级引发的性能血案 - 王者归来

上次老码农在一场版本升级引发的性能血案 - 之数据历险一文中讲得口吐白沫, 最后还是没有一个结果, 反而被 OSCer 们各种吐槽: "看得我快快精尽人亡了""看着一头雾水""一脸懵逼进来,一脸懵逼...

罗格林
2018/06/04
0
0
全程回放:100T核心数据库升级历险记(附PPT)

本文根据汪洋老师在〖2016 Gdevops全球敏捷运维峰会广州站〗现场演讲内容整理而成。 src="https://mmbiz.qlogo.cn/mmbizjpg/tibrg3AoIJTusqZtiaNH85zAgnZWmpvCD0M71ibW4xHL7m26v8pd81wh7rS6g......

汪洋
2017/04/19
0
0
“2017年度十大MVP”入选者干货好文回顾

“2017年度十大MVP评选”开始征集大众投票啦!为了方便大家回顾各位MVP入选者在这一年来的精彩技术贡献,投出你最宝贵的一票,小编在此整理了一份原创文章合集,点击文章标题即可阅读全文! ...

2017/11/10
0
0
你曾错过的2017十大MVP精彩好文,今天Repo回来!

“2017年度十大MVP评选”已圆满落幕,再次感谢这10位获奖专家及团队为知识传播的努力、对技术分享的热忱、为行业发展的贡献,在此将他们这一年来分享过的干货好文遴选出来,以便大家温故知新...

DBAplus社群
2017/11/20
0
0
Mybatis 错误Should be: #{propName,attr1=val1,attr2

Improper inline parameter map format. Should be: #{propName,attr1=val1,attr2; <update id="updateByPrimaryKeySelective" parameterType="com.wlyd.fmcgwms.persistence.beans.basic.W......

boonya
2016/04/22
50
0

没有更多内容

加载失败,请刷新页面

加载更多

用Javascript评估用户输入密码的强度

密码已经是我们生活工作中必不可少的工具,但一个不安全的密码有又有可能会给我们造成不必要的损失。作为网站设计者,如果我们在网页中能对用户输入的密码进行安全评估,并显示出相应的提示信息...

花漾年华
24分钟前
0
0
Python 打开目录与指定文件

Python打开外部文件有很多方法, os.popen打开外部程序,但发现只能打开文件所在目录的文件 os.system可打开外部文件os.system(command) command 要执行的命令,相当于在Windows...

shzwork
26分钟前
2
0
Leetcode # 118:Pascal's Triangle 杨辉三角

118:Pascal's Triangle 杨辉三角 Given a non-negative integer numRows, generate the first numRows of Pascal's triangle. 给定一个非负整数 *numRows,*生成杨辉三角的前 numRows 行。 ......

iCodeBugs
36分钟前
1
0
IntelliJ IDEA导入Gradle项目

1.File > Open 找到项目后选择build.gradle文件,点击ok image 2.点击Open as Project image 3.选择本地Gradle以及JDK image 4.点OK完成...

青峰Jun19er
40分钟前
1
0
Python实现斐波那契数列

斐波那契数列大家都很熟悉吧,咱们在高中学数学的时候,老师会讲这个定律以及算法,其实数据结构和数学息息相关,数学思维好的往往逻辑思维就比较好,今天小猿圈带大家学习一下python的斐波那...

小猿圈加加
41分钟前
3
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部