在日常Java开发中,异步线程处理相关业务是司空见惯的事,在异步线程处理监控中又经常会对其执行时间进行监控分析,比如运行时间是否超时等。这种方法在正常运行的时间是没有问题的,比如发起一个socket请求,服务端在10s内无应答则判断为超时,这样的逻辑是没有问题的;但这种机制忽略了一个Full GC机制,就是在极端情况下,当获取startTime开始时间后,此时发生了Full GC,触发了STW所有线程停止等待垃圾回收,并且这个GC时间不短,那就容易对超时判断造成了影响。如下例子:
long start = System.currentTimeMillis();
//模拟请求
Thread.sleep(4000);
if (new Random().nextBoolean()) {
//此时发生了Full GC,此GC耗费了10s
Thread.sleep(2000);
}
//判断是否超时
if (System.currentTimeMillis() - start > 5000) {
System.out.println("请求超时");
}
根据上述代码,原来代码的业务执行大概需要4秒,但代码执行过程中JVM会随机进入Full GC,耗时2秒,那此时总流程会耗费6秒;但在后面判断时是以是否大于5秒来判断是否超时,这样会将本来正常的请求也被列入异常异常,这明显不是设计的初衷。
因此,在代码开发中碰到需要用耗时来判断是否存在异常时,就需要排除Full GC对其耗时的影响。
如下代码中就实现了判断是否经历过Full GC,从而排除对计时的影响:
public class TestStopSatch {
public static void main(String[] args) throws InterruptedException, TimeoutException {
long st = System.currentTimeMillis();
StopWath stopWath = new StopWath();
stopWath.start();
//设置超时时间为20秒
long et = st + 20000;
long nextLogTime = st + 1000;
while (true) {
//开始计时
stopWath.restart();
System.out.println("处理业务逻辑,满足则return");
long now = System.currentTimeMillis();
if (now > nextLogTime) {
nextLogTime = now + 1000;
}
long rem = et - now;
if (rem <= 0) {
//此处加个判断是否发生了full gc,如果发生了则需要排除full gc的时间影响
if (stopWath.getElapse() > 5000) { //通过是否大于5秒来判断是否发生full gc
//则需要延长超时的时间,重置超时时间
et = et + stopWath.getElapse();
} else {
//程序超时
throw new TimeoutException();
}
}
rem = Math.min(rem, nextLogTime - now);
rem = Math.max(rem, 1);
stopWath.restart();
//此时也需要排除full gc对线程等待的影响
wait(rem);
//排除full gc的影响
if (stopWath.getElapse() > 5000) {//通过是否大于5秒来判断是否发生full gc
//则需要延长超时的时间,重置超时时间
et = et + stopWath.getElapse() - rem;
}
}
}
public static class StopWath {
//开始时间
long start = 0L;
//统计流逝的时间
long elapse = 0L;
public StopWath() {
}
/**
* 重置时间
*
* @return StopWath
*/
public StopWath reset() {
//开始时间
start = 0L;
//统计时间流逝的时间
elapse = 0L;
return this;
}
/**
* 开始计时
*
* @return StopWath
*/
public StopWath start() {
start = System.currentTimeMillis();
return this;
}
/**
* 重新计时
*
* @return StopWath
*/
public StopWath restart() {
return this.reset().start();
}
/**
* 计算流逝的时间
*
* @return StopWath
*/
public long getElapse() {
return System.currentTimeMillis() - start;
}
}
}