记一次drools5的性能优化过程

作者: 小菜Yang | 来源:发表于2018-11-01 16:26 被阅读225次

业务场景

支付平台每日早晨会收到账务系统发送的批量扣款指令，这些扣款指令需要通过支付路由系统获取到最优的扣款支付渠道，进而再通过支付网关系统送往各个支付渠道进行扣款。为了保证扣款成功率及批扣的回盘速度，这些批量扣款指令需要在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方式来解决性能问题（有局限性，需要结合自己业务规则），也算是一个新的解决问题的思路。记录一下，也希望能够帮到大家

记一次drools5的性能优化过程

业务场景

遇到的问题

运行环境

猜想一 JVM GC引起的停顿引起性能下降

猜想二 drools5 StatefulKnowledgeSession创建速度慢

解决方案一：提升StatefulKnowledgeSession的创建速度

解决方案二：维护StatefulKnowledgeSession池，从池子里获取，不必每次都创建session

结语

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

支付路由