业务场景
支付平台每日早晨会收到账务系统发送的批量扣款指令，这些扣款指令需要通过支付路由系统获取到最优的扣款支付渠道，进而再通过支付网关系统送往各个支付渠道进行扣款。为了保证扣款成功率及批扣的回盘速度，这些批量扣款指令需要在1小时内全部发出。
系统调用链如下：
账务->支付批处理->支付路由->支付网关->支付公司
遇到的问题
在对公司PAY2.0的支付路由模块（采用Drools5实现）改造过程中，跑批压测发现随着并发的增大，路由处理的速度会急剧下降，单批路由（1000笔/批）的速度为10s左右，但压测过程中，单批路由的速度下降到120s+，这个速度显然是不可接受的。
运行环境
- drools版本：5.2.1.Final
- JDK版本： 1.8.0_131-b11
- 数据量：20个并发线程，发送500批指令，一批1000笔交易，共计50万笔
- JVM关键参数：
-Xms4096m -Xmx4096m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSScavengeBeforeRemark
猜想一 JVM GC引起的停顿引起性能下降
鉴于目前的问题，在单批发送性能正常，压测多批并发发送性能下降。首先想到的是内存不足导致的FGC频繁引起的性能下降。
验证思路：
- 在压测过程中，关注GC情况（YGC， FGC的频率）
执行命令：jstate -gccause pid 3s （每3秒打印一次gc情况）
关注GC情况，发现在处理过程中,FGC次数并没有上涨，YGC频率大概为1次/每秒。GC情况并无异常，具体GC频率见下方：
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC
11.04 0.00 21.89 10.31 98.36 96.54 26 1.064 3 0.498 1.562 Allocation Failure No GC
0.00 4.25 13.30 13.70 98.19 96.58 29 1.320 3 0.498 1.818 Allocation Failure No GC
47.24 0.00 33.61 13.81 98.22 96.59 30 1.381 3 0.498 1.878 Allocation Failure No GC
7.47 0.00 87.75 16.89 98.22 96.59 32 1.528 3 0.498 2.025 Allocation Failure No GC
0.00 14.26 58.33 19.81 98.23 96.60 35 1.720 3 0.498 2.218 Allocation Failure No GC
0.00 99.23 29.08 20.59 98.24 96.60 37 1.819 3 0.498 2.317 Allocation Failure No GC
0.00 11.17 64.61 23.57 98.24 96.60 39 1.957 3 0.498 2.455 Allocation Failure No GC
17.95 0.00 40.54 26.48 98.25 96.60 42 2.163 3 0.498 2.661 Allocation Failure No GC
42.66 0.00 70.69 27.96 98.26 96.60 44 2.282 3 0.498 2.780 Allocation Failure No GC
0.00 28.83 29.59 30.94 98.27 96.60 47 2.454 3 0.498 2.952 Allocation Failure No GC
12.97 0.00 0.00 34.06 98.28 96.60 50 2.687 3 0.498 3.185 Allocation Failure No GC
19.40 0.00 4.89 36.77 98.32 96.60 52 2.836 3 0.498 3.333 Allocation Failure No GC
0.00 7.05 90.22 37.37 98.32 96.60 53 2.856 3 0.498 3.354 Allocation Failure No GC
6.87 0.00 37.19 40.67 98.33 96.60 56 3.013 3 0.498 3.510 Allocation Failure No GC
0.00 8.02 32.79 43.91 98.33 96.60 59 3.170 3 0.498 3.668 Allocation Failure No GC
0.00 37.64 32.00 45.72 98.34 96.60 61 3.250 3 0.498 3.747 Allocation Failure No GC
0.00 45.11 45.23 47.08 98.35 96.60 63 3.310 3 0.498 3.808 Allocation Failure No GC
0.00 21.09 68.87 49.82 98.36 96.60 65 3.407 3 0.498 3.905 Allocation Failure No GC
- 应用日志与GC日志进行对比：抽查执行速度较慢的一笔交易的时间与对应的GC日志做比对，看看在此时间范围内，是否存在GC
2018-10-25 19:22:09.494 INFO 26473 --- [http-nio-11255-exec-11] c.m.p.s.r.RouteRuleEnableServiceImpl : [TxId: , SpanId : ] 交易码转换校验成功：客户端输入交易码“batchDeduct”与路由交易码“batchDeduct”一致
2018-10-25 19:22:09.494 INFO 26473 --- [http-nio-11255-exec-11] c.m.p.s.r.RouteRuleEnableServiceImpl : [TxId: , SpanId : ] transId(batchDeduct_20171129204888_psbc)禁用日期无限制
2018-10-25 19:22:09.495 INFO 26473 --- [http-nio-11255-exec-11] c.m.p.s.r.t.RouteAnalyzeResultToolImpl : [TxId: , SpanId : ] 规则引擎输入{"deptName":"邮政储蓄银行"***********4****777000}
2018-10-25 19:22:09.559 INFO 26473 --- [http-nio-11255-exec-11] c.m.p.s.runtime.route.DroolsServiceImpl : [TxId: , SpanId : ] StopWatch 'initStatefulKSession': running time (millis) = 64
2018-10-25 19:22:09.559 INFO 26473 --- [http-nio-11255-exec-11] c.m.p.s.r.t.RouteAnalyzeResultToolImpl : [TxId: , SpanId : ] 规则引擎输出|
根据上述的应用日志，发现在2018-10-25 19:22:09.495~2018-10-25 19:22:09.559时间段，drools规则引擎执行花费了64ms（正常情况下应该是小于1ms的）
检查该时间段的GC日志，并无CMS GC日志，只有一些YGC日志，YGC执行速度很快，不是引起性能较低的原因。
2018-10-25T19:22:07.631+0800: 3.261: [GC (Allocation Failure) 2018-10-25T19:22:07.631: 3.262: [ParNew: 69376K->4561K(78016K), 0.0044468 secs] 69376K->4561K(251456K), 0.0046933 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2018-10-25T19:22:08.457+0800: 4.087: [GC (Allocation Failure) 2018-10-25T19:22:08.457: 4.087: [ParNew: 73937K->3882K(78016K), 0.0100274 secs] 73937K->6276K(251456K), 0.0101941 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2018-10-25T19:22:08.982+0800: 4.612: [GC (Allocation Failure) 2018-10-25T19:22:08.982: 4.613: [ParNew: 73258K->7480K(78016K), 0.0045377 secs] 75652K->9874K(251456K), 0.0046866 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
2018-10-25T19:22:09.587+0800: 5.217: [GC (Allocation Failure) 2018-10-25T19:22:09.587: 5.217: [ParNew: 76856K->6642K(78016K), 0.0097580 secs] 79250K->13712K(251456K), 0.0099389 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
根据以上的GC分析，认定了性能的降低与垃圾回收无关。
猜想二 drools5 StatefulKnowledgeSession创建速度慢
在进行GC排查时，抽样了应用日志，发现StatefulKnowledgeSession的创建速度并不稳定，并发上去后，StatefulKnowledgeSession的创建速度会变得越来越慢，最高甚至达到100ms+的消耗。
写了一个测试类，模拟测试环境不停的进行session创建，并使用jprofiler工具进行监控，发现session创建的耗时在于Class.forName的反射上。如下图所示：
StatefulSession-trace.png
根据线程执行堆栈，找到耗时的逻辑代码ProcessRuntimeFactory.java，
这个类存在一个static的全局变量ProcessRuntimeFactoryService provider，获取这个provider之前会进行空判断，如果为空则需要调用loadProvider()方法进行初始化。继续观察loadProvider()，发现会执行一段代码：
Class.forName("org.jbpm.process.instance.ProcessRuntimeFactoryServiceImpl")由于我们的项目并没有依赖jbpm的包，所以这个Class.forName方法会一直报错，引起provider永远没办法初始化成功，一直为空，所以每一次session的创建，都需要经过这个loadProvider()的过程，这代表每一次session的创建都要进行Class.forName的操作。而且该操作是效率是比较低的，从而拉低了整个session的创建速度。
public static synchronized ProcessRuntimeFactoryService getProcessRuntimeFactoryService() {
if (provider == null) {
loadProvider();
}
return provider;
}
private static void loadProvider() {
ServiceRegistryImpl.getInstance().addDefault( ProcessRuntimeFactoryService.class, "org.jbpm.process.instance.ProcessRuntimeFactoryServiceImpl" );
setProcessRuntimeFactoryService(ServiceRegistryImpl.getInstance().get( ProcessRuntimeFactoryService.class ) );
}
解决方案一：提升StatefulKnowledgeSession的创建速度
要加快StatefulKnowledgeSession的创建速度，那么就要避免每一次创建都去进行Class.forName的操作。两个方案：
- 新建一个类，实现ProcessRuntimeFactoryService接口，并在项目启动后，实例化这个类名，通过反射方式为ProcessRuntimeFactory.provider进行赋值。
- 引入jbpm的包。这样执行Class.forName就不会报错，provider可以正常初始化。
Class.forName("org.jbpm.process.instance.ProcessRuntimeFactoryServiceImpl")
以上的两个方案实际并不友好，虽然提高了StatefulKnowledgeSession创建速度，但“provider为空的情况下创建的ksession”这个逻辑已经在线上验证过一段时间，现在为provider赋值，不知道会不会引起其他的逻辑BUG，所以此方案放弃
解决方案二：维护StatefulKnowledgeSession池，从池子里获取，不必每次都创建session
- 维护StatefulKnowledgeSession池，共享KSession，避免了KSession的创建开销。能够极大的提升系统drools处理性能。
- 支付的路由drools逻辑仅仅为“判断类”，在drools规则里，并没有修改facthandles对象的操作和及创建其他影响路由结果的变量。 可以认为是一个内部“无状态”的逻辑片段（这一点及其重要，不满足此条件共用ksession会引发规则引擎结果错乱的问题）。只要保证一个ksession在同一时刻只有一个线程持有，并在线程处理结束将kseesion归还给池子之前，清除当前线程插入业务对象FactHandle，即可保证归还给池子的kession是“干净”，“无污染”的
基于以上两点分析，决定采用此方案进行性能优化，StatefulKnowledgeSession池的维护使用Apache旗下的common-pool2的开源工具类实现。common-pool2的使用此处不在赘述，仅说下几个要点：
- 从池子获取ksession时，要考虑如果获取不到的方案，是阻塞等待还是重新创建一个kssion返回。 阻塞等待的话阻塞等待多长时间？ 重新创建的话该ksession并不在pool的维护中，所以使用完后必须要调用dispose()方法释放资源。我采用的是第2个方法，逻辑如下代码：
/**
* 从池子中获取对象
* @return
*/
public StatefulKnowledgeSessionWrapper borrowObject() {
try {
return new StatefulKnowledgeSessionWrapper(StatefulKnowledgeSessionWrapper.SessionFrom._pool, pool.borrowObject());
} catch (Exception e) {
logger.warn("从DroolsSession池中获取对象异常(程序重新创建一个Session返回)", e);
return new StatefulKnowledgeSessionWrapper(StatefulKnowledgeSessionWrapper.SessionFrom._new, factory.initDroolsStatefulSession());
}
}
public void returnObject(StatefulKnowledgeSessionWrapper sessionWrapper) {
for (FactHandle handle : sessionWrapper.getSession().getFactHandles()) {
//清理插入的fact对象
sessionWrapper.getSession().retract(handle);
}
if (sessionWrapper.getSessionFrom() == StatefulKnowledgeSessionWrapper.SessionFrom._pool) {
//归还池子，销毁的动作见：DroolsSessionFactory.destroyObject
pool.returnObject(sessionWrapper.getSession());
}
if (sessionWrapper.getSessionFrom() == StatefulKnowledgeSessionWrapper.SessionFrom._new) {
//new出来的session 直接释放资源
sessionWrapper.getSession().dispose();
}
}
- ksession-pool的空闲对象回收时，一定要做资源释放dispose()
@Override
public void destroyObject(PooledObject<StatefulKnowledgeSession> p) throws Exception {
StatefulKnowledgeSession session = p.getObject();
//销毁前释放资源
session.dispose();
}
结语
通过方案二的处理，目前在相同运行环境下，压测每批交易的路由执行速度均能稳定在10s以内。
drools5的官方推荐使用方式，StatefulKnowledgeSession都是新new出来的，但在此我们使用的是共享session方式来解决性能问题（有局限性，需要结合自己业务规则），也算是一个新的解决问题的思路。记录一下，也希望能够帮到大家
