自定义方法耗时监控告警
用于记录代码耗时,当代码耗时超过指定阈值时打印告警日志
自定义注解
通过自定义注解的方式可以更方便的使用,只需要在需要做耗时兼容的方法上增加上该注解即可
package com.huakai.springenv.aspect.profiler;
import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Documented
@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface DBTimeProfiler {
}
自定义切面
需要注意的时这里使用Spring aop实现,如果是是使用this(或者省略)调用bean内部方法将导致代理失效,进而导致监控失效
package com.huakai.springenv.aspect.profiler;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
@Aspect
@Component
public class TimeProfileAspect {
@Around("execution(* *.*(..)) && @annotation(com.huakai.springenv.aspect.profiler.DBTimeProfiler)")
public Object catTransactionAspect(ProceedingJoinPoint joinPoint) throws Throwable{
MethodSignature signature = (MethodSignature) joinPoint.getSignature();
DBTimeProfiler timeProfiler = signature.getMethod().getAnnotation(DBTimeProfiler.class);
if(timeProfiler == null){
return joinPoint.proceed();
}
String methodName = signature.getMethod().getName();
DBTimeProfile.enter(signature.getMethod().getDeclaringClass().getSimpleName() + "." + methodName);
try{
return joinPoint.proceed();
}finally{
DBTimeProfile.release();
}
}
}
自定义处理
package com.huakai.springenv.aspect.profiler;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import javax.servlet.http.HttpServletRequest;
import java.util.*;
/**
* 用于记录代码耗时,当代码耗时超过指定阈值时打印告警日志
*/
public class DBTimeProfile {
private static final Logger log = LoggerFactory.getLogger(DBTimeProfile.class);
private static final ThreadLocal<LinkedList<TimeProfileElement>> logs = new ThreadLocal<>();
private static final ThreadLocal<TimeProfileElement> currentElement = new ThreadLocal<>();
private static final ThreadLocal<HttpServletRequest> request = new ThreadLocal<>();
private static final ThreadLocal<Integer> currentThreshold = new ThreadLocal<>();
private static volatile int threshold = 100;// 超时时间,单位毫秒
private static final String timeout = "DBTimeProfile timeout ";
private DBTimeProfile() {
}
private static void enter() {
enter("");
}
/**
* 在需要监控耗时的方法体前调用
*
* @param tag 方法体的名字
*/
public static void enter(String tag) {
if (logs.get() == null) {
return;
}
TimeProfileElement cur = currentElement.get();
TimeProfileElement t = new TimeProfileElement();
t.logEnterTime();
t.setTag(tag);
t.parent = cur;
t.setDeep(cur == null ? 0 : cur.getDeep() + 1);
currentElement.set(t);
logs.get().add(t);
}
/**
* 在需要监控耗时的方法体后调用
*/
public static void release() {
LinkedList<TimeProfileElement> s1 = logs.get();
TimeProfileElement cur = currentElement.get();
if (s1 == null || cur == null) {
return;
}
if (s1.size() <= 1) {
// throw new IllegalStateException("release failed,will stop this timeProfile, enter/release 必须成对出现");
log.warn("release failed,will stop this timeProfile, enter/release 必须成对出现", new IllegalStateException());
clear();
return;
}
cur.logReleaseTime();
currentElement.set(cur.parent);
}
/**
* 在Filter等入口处调用,开始计时
*/
public static void start() {
logs.set(new LinkedList<>());
enter();
}
/**
* 在Filter等入口处调用,开始计时
*/
public static void start(HttpServletRequest httpServletRequest) {
logs.set(new LinkedList<>());
request.set(httpServletRequest);
enter();
}
/**
* 在Filter等入口处调用,结束当前计时
*/
public static void end() {
end("undefined");
}
/**
* 在Filter等入口处调用,结束当前计时,如果超过日志,会打印告警日志
*/
public static void end(String methodName) {
TimeProfileElement cur = currentElement.get();
if (cur == null) {
return;
}
if (cur.parent != null) {
log.warn("timeProfile methodName:{} failed, enter/release 必须成对出现", methodName);
clear();
return;
}
cur.logReleaseTime();
long timeConsume = cur.getCostTimeMillis();
Integer threshold = currentThreshold.get();
if (threshold == null) {
threshold = DBTimeProfile.threshold;
}
if (cur.getCostTimeMillis() > threshold) {
// 输出日志
StringBuilder sb = new StringBuilder();
HttpServletRequest httpRequest = request.get();
if (httpRequest != null) {
sb.append(timeout).append(timeConsume).append("ms >").append(threshold).append("ms, url=").append(httpRequest.getRequestURI());
} else {
sb.append(timeout).append(timeConsume).append("ms > methodName:").append(methodName);
}
List<TimeProfileElement> list = new ArrayList<>(logs.get());
for (TimeProfileElement s : list) {
sb.append("\r\n\t");
for (int i = 0; i < s.getDeep(); i++) {
sb.append("-");
}
Long consume = s.getCostTimeMillis();
sb.append(consume * 100 / timeConsume).append("%");
sb.append(" ").append(consume).append("ms");
if (s.getTag() != null) {
sb.append(" ").append(s.getTag());
}
}
log.warn("{}", sb);
}
clear();
}
private static void clear() {
request.remove();
currentElement.remove();
logs.remove();
currentThreshold.remove();
}
/**
* 设置报警阈值,这是全局配置,只要在应用启动时设置一次即可,单位:ms
* <br/>
*
* @param threshold 告警阈值
*/
public static void setThreshold(int threshold) {
DBTimeProfile.threshold = threshold;
}
/**
* 设置当前线程调用栈的报警阈值,这个配置只会在当前线程、本次监控生效。
*
* @param threshold 告警阈值
*/
public static void setCurrentThreshold(int threshold) {
currentThreshold.set(threshold);
}
/**
* 获取当前线程的报警报警阈值
*
* @return 告警阈值
*/
public static Integer getCurrentThreshold() {
return currentThreshold.get();
}
private static class TimeProfileElement {
// 基线时间,为了减小timeMillis的占用空间
private static final long BASE_TIME = System.currentTimeMillis();
private int timeMillis;
private int deep;
private String tag;
private TimeProfileElement parent;
void logEnterTime() {
timeMillis = (int) (System.currentTimeMillis() - BASE_TIME);
}
void logReleaseTime() {
timeMillis = (int) (System.currentTimeMillis() - BASE_TIME - timeMillis);
}
long getCostTimeMillis() {
return timeMillis;
}
int getDeep() {
return deep;
}
void setDeep(int deep) {
this.deep = deep;
}
String getTag() {
return tag;
}
void setTag(String tag) {
this.tag = tag;
}
}
}
测试
测试类
package com.huakai.springenv.service.impl.timeprofiler;
import com.huakai.springenv.aspect.profiler.DBTimeProfiler;
import com.huakai.springenv.utils.SleepUtils;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;
import javax.annotation.Resource;
@Service
@Slf4j
public class TimeProfilerService {
/**
* 引入Spring代理过后的对象,否则无法被aop增强
*/
@Resource
private TimeProfilerService self;
@DBTimeProfiler
public void method() {
SleepUtils.workTime(200);
log.info("{}#{} completed", getClass().getName(), Thread.currentThread().getStackTrace()[1].getMethodName());
self.method2();
}
@DBTimeProfiler
public void method2() {
SleepUtils.workTime(400);
log.info("{}#{} completed", getClass().getName(), Thread.currentThread().getStackTrace()[1].getMethodName());
self.method3();
}
@DBTimeProfiler
public void method3() {
SleepUtils.workTime(600);
log.info("{}#{} completed", getClass().getName(), Thread.currentThread().getStackTrace()[1].getMethodName());
}
}
测试方法
package com.huakai.springenv.service;
import com.huakai.springenv.aspect.profiler.DBTimeProfile;
import com.huakai.springenv.service.impl.timeprofiler.TimeProfilerService;
import org.junit.jupiter.api.Test;
import org.springframework.boot.test.context.SpringBootTest;
import javax.annotation.Resource;
@SpringBootTest
class TimeProfilerServiceTest {
@Resource
private TimeProfilerService timeProfilerService;
@Test
void timeProfilerTest() {
try {
DBTimeProfile.start();
timeProfilerService.method();
}finally {
DBTimeProfile.end( Thread.currentThread().getStackTrace()[1].getMethodName());
}
}
}
结果
2024-07-14 20:06:41.499 INFO 13900 --- [ main] c.h.s.s.i.t.TimeProfilerService : com.huakai.springenv.service.impl.timeprofiler.TimeProfilerService#method completed
2024-07-14 20:06:41.900 INFO 13900 --- [ main] c.h.s.s.i.t.TimeProfilerService : com.huakai.springenv.service.impl.timeprofiler.TimeProfilerService#method2 completed
2024-07-14 20:06:42.501 INFO 13900 --- [ main] c.h.s.s.i.t.TimeProfilerService : com.huakai.springenv.service.impl.timeprofiler.TimeProfilerService#method3 completed
2024-07-14 20:06:42.501 WARN 13900 --- [ main] c.h.s.aspect.profiler.DBTimeProfile : DBTimeProfile timeout 1209ms > methodName:timeProfilerTest
100% 1209ms
-99% 1206ms TimeProfilerService.method
--82% 1002ms TimeProfilerService.method2
---49% 601ms TimeProfilerService.method3
ps:DBTimeProfile.start() & DBTimeProfile.end()
可以放到Web过滤器中,这样便可以更便捷的监控接口的耗时,监控接口耗时,也可以放到自定义线程中,监控线程执行耗时