循环调用spring service层耗费时间很长的问题排查记录

背景

　　最近有一个项目，就是将业务数据推送到第三方平台去，每天定时跑任务，代码完成后测试发现性能很慢，100万的数据，大约1小时40分钟才处理完成，于是开始分析程序哪些部分可能导致程序很慢。

排查

分析业务

第一次分析

从业务程序上面分析，每次JOB处理过程中可能耗时的操作有两个，一是从数据库批量查询出1000条记录，二是将这些数据处理后通过http请求每次500条记录提交到第三方平台。于是添加处理时间的日志观察：

• 每次请求数据库的时间是正常的，每次请求的时间大约为300-400ms。
• 每次提交数据到第三方平台的处理时间也正常，每次请求时间大约1000-2000ms。

以上两个时间是正常的，如果忽略其他时间，按照上面处理时间的话，100万条记录大约20分钟就处理完了，所以耗时多的问题不是在这两步出现的。

第二次分析

程序逻辑是JOB启动后，单线程从数据库查询出1000条记录，然后每条记录通过线程池（线程数量设置为2，可动态调整）处理每条记录，并将处理的结果放入全局集合中，如果集合元素数量满了500条记录，就将这500条记录推送给第三方平台。JOB启动的单线程则继续从数据库查询数据，线程池的任务队列2000（new LinkedBlockingQueue<Runnable>(2000)），拒绝策略是调用者执行（new ThreadPoolExecutor.CallerRunsPolicy()）。

　　从日志中看到每次数据库查询完成后，要等10s左右时间才能下次再查询数据库。所以耗时应该是数据库查询完成后的某些操作很慢导致线程池队列满了，并且使用调用者执行了。继续打印每次任务执行的时间，发现有个获取队列长度的的逻辑前后时间很长，将近20ms：

int nums = service.getNumsOfXtreamPushOneTime();
getNumsOfXtreamPushOneTime方法如下：

public static int getNumsOfXtreamPushOneTime() {
    String numsOfXtreampushOnetime = DiamondManager.getDiamondCommValue(AppConsts.numsOfXtreamPushOnetime);
    return NumberUtils.isNumber(numsOfXtreampushOnetime) ? NumberUtils.toInt(numsOfXtreampushOnetime) : 500;
}

这个方法很简单，就是获取配置的数量转换成数字，没有其他逻辑了，怎么会这么长时间呢，每次20ms的话，500次循环就是10s的时间，问题出在这里了。
将方法inline处理再看时间，每次0ms。所以应该是将方法放到service中导致时间变长的，该service为spring bean，然后包路径处于oracle下面，猜测service应该是AOP了其他业务导致的了，去查看配置信息找到

从这里看到oracle包下面的Impl中的方法都有加入事务处理，所以之前的方法service.getNumsOfXtreamPushOneTime()在调用前后都会有开启和关闭事务的处理，虽然没有数据库语句操作，但是需要连接数据库处理事务，所以每次调用大约有20ms左右的耗时。

好了，知道原因修改就简单了，将这个方法从spring bean提取出到util类中，再跑测试。几乎没有等待，每次查询完成数据库就推送给第三方平台。100万条数据大约十多分钟搞定了。

 

总结

spring bean的处理逻辑很可能会被AOP加入其它业务逻辑，在涉及到大循环处理的时候，一定要看看是否有其他不必要的处理包含在里面。