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

[greenlaw110]

1. 案情回顾

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

1.1 JSON 测试结果比较

TFB JSON - act-1.8.2

TFB JSON - act-1.8.8-RC6

1.2 单次查询测试结果比较

TFB Single Query - act-1.8.2

TFB Single Query - act-1.8.8-RC6

1.3 多次查询测试结果比较

TFB Multiple Queries - act-1.8.2

TFB Multiple Queries - act-1.8.8-RC6

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

TFB Fortunes - act-1.8.2

TFB Fortunes - act-1.8.8-RC6

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

TFB Updates - act-1.8.2

TFB Updates - act-1.8.2

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

TFB Plaintext - act-1.8.2

TFB Plaintext - act-1.8.8-RC6

数据不会说谎, 可以看出老码农的努力让 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 连接刚刚启动的进程:

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

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

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

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

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

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

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

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

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

我们先保存为 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 秒, 结果如下:

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

1.8.1 (Good one)

1.8.8-RC6 (Bad one)

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

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

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

1.8.1

1.8.8-RC6

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

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

1.8.1

1.8.8-RC6

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

3. 结局

老码农第一个深入研究的问题: 为啥 Connection 会 rollback, 这与 prepareStatement 不停调用有何关联, 结果是给 Eclipselink 项目提了一个 Issue 报告, 具体内容也是 TLDR, 欲知详情, 移步这里: eclipse-ee4j/eclipselink#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() {...}

2. 如果用户没有指定事务, 则系统从 Dao 操作来判断, 对于 select, count 等操作, 都不启动事务, 对于 save, update, delete 等操作则判断是否存在事务, 如果没有, 则启动读写事务.

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

咱们下回分解