1.前言
在日常工作中,我们常常会遇到随着业务的发展,系统的性能逐渐无法满足业务需求,这个时候就需要系统进行技术改造或者性能调优。技改可能会包括系统的重构甚至重写,功能的重新划分,但是只要是找了性能的瓶颈点,也许只是一些jvm参数或者常量的调优。
2.优化
为了寻找系统的性能瓶颈点,如果有一套完整图形化的监控系统固然是好事,但是很多情况都可能无法满足这个要求,更多的是通过日志来完成。因此,在合理的地方打印日志尤为重要。
上周某日下午,一个线上系统开始打印大量错误日志,查看日志发现错误基本为数据库唯一键冲突,通过分析发现日志发现该系统(下面以系统A称呼)的奖励发放功能在上一个奖罚发放还没有完成的情况下,又触发了新的奖励发放调用,奖励发放未半小时触发一次。因为奖励发放逻辑没有做并发同步处理,导致数据落库的时候发生唯一键冲突。因为是离线发放逻辑不考虑实时性,而且当前的数据量可以通过单机多线程并发处理,所以一方面通过redis锁保证同一时间只有一个奖励发放在处理,另一方面通过进行系统优化,尽可能的降低一次奖励发放的耗时。
系统A的处理逻辑为,系统A会定时收到系统B的调用,一次消息代表一次奖励发放任务,一次任务包含多个司机,需要分别对多个司机进行奖励发放。基本的处理逻辑是系统A在被调用后,获取任务所需基本信息,分批获取相关司机,多线程执行发放任务,每一次submit任务后都会sleep50毫秒,最后通过countdown同步等待异步任务处理完成,在整个任务的开始和结束的时候都会打印日志。为了确认单个任务的耗时,实现了下面的wrapper类
public class MarketingRunnableWrapper implements Runnable {
private static final ILog logger = LogFactory.getLog("threadLogger");
//任务名
private String taskName;
//任务创建时间
private Long taskCreateTime;
//日志flag
private String flag;
private Runnable runnable;
public MarketingRunnableWrapper(Runnable runnable) {
this(runnable, "");
}
public MarketingRunnableWrapper(Runnable runnable, String taskName) {
this.runnable = runnable;this.taskName = taskName;
this.taskCreateTime = System.nanoTime();
this.flag = LogFactory.getFlag();
}
@Override
public void run() {
Long beginTime = System.nanoTime();
try {
runnable.run();
} catch (Exception e) {
String msg = "task: " + taskName + " run throw exception";
msgLog(msg, e);
} finally {
String msg = String.format(
"task: %s executed, thread name = %s, delay time = %s ms, executing time = %s ms", taskName,
Thread.currentThread().getName(), (beginTime - taskCreateTime) / 1000000,
(System.nanoTime() - beginTime) / 1000000);
msgLog(msg, null);
}
}
private void msgLog(String msg, Exception e) {
LogFactory.setFlag(flag);
if (e == null) {
logger.info(msg);
} else {
logger.error(msg, e);
}
LogFactory.removeFlag();
}
}
该wrapper类实现了Runnable接口,打印一次task的执行的等待耗时和执行耗时。
根据日志打印和程序常量得到如下数据表:
| 总耗时 Ttotal(s) | 任务数Nt | 总耗时 Ttotal/任务数Nt(ms) | 任务总耗时Ttt(ms,相加耗时) | 平均Taver/最大任务耗时Tmax(ms) | 核心Ntcore/最大线程数Ntm | 平均Taver/核心Ntcore(ms) |
任务奖励(奖励) | 126.000 | 2437 | 51.72 | 27344 | 11.22/43 | 10/10 | 1.1 |
上述表格中Ttt和Taver、Tmax都是从单线程的角度来说明的
- 数据计算
任务添加等待时长Tw = 50ms
如果满线程跑的话,平均单个任务执行实际耗时Tstrt = Taver/Ntcore = 1.1ms
Tw远远大于Tstrt说明,基本只有一个线程在跑,而且还是跑跑停停,没有发挥多线程的优势
- 分析
因为Twt大于Tstrt,说明添加等待限制了线程池的性能
平均每个任务执行实际耗时Trorign = Ttotal/Nt = 126000/2437 = 51.72ms ~ Tw(这也说明主要花在了等待上面)
- 优化方案
将等待时间Tw修改为5ms
等待时间优化后,数据如下:
| 总耗时 Ttotal(s) | 任务数Nt | 实际平均任务耗时Trtapt (总耗时 Ttotal/任务数Nt(ms)) | Tw | 任务总耗时Ttt(ms,相加耗时) | 平均Taver/最大任务耗时Tmax(ms) | 核心Ntcore/最大线程数Ntm | 理论平均任务耗时Tctapt (平均Taver/核心Ntcore(ms)) |
任务奖励(奖励) | 415.088 | 36259 | 11.5 | 10 | 1253473 | 34.56/147 | 10/10(公用) | 3.5 |
从上面这个表可以看出Trtapt比Tctapt大,但是与Tw相近,说明现在主要的耗时还是由Tw,任务插入等待决定,所以还有一定的优化空间,但是相比之前的的吞吐量,提高了接近五倍。
那是否可以去掉插入等待的时间,直接将任务插入到队列中呢。由于为了保证内存空间不会OOM,一般会设置一个相对合理的队列长度,这样的话就是需要保证队列长度足够长,使得任务可以大批量的插入而不会block,或者设置合理的队列满的处理逻辑,而且较大的队列长度存在对内存空间的压力以及fullgc的风险。因此设置一个合理的任务插入等待时间和一个合理的队列长度(不用太大),可以保证相对较高的吞吐量。