perf4j 监控请求 + traceId区分日志
1. 场景
从request进入Controller到出去的时间, 可以统计接口访问的一些数据，如：平均处理时间、最大处理时间
2. 代码
2.1 mvc-servlet 定义切面和拦截器
<?xml version="1.0" encoding="UTF-8"?> <beans xmlns="http://www.springframework.org/schema/beans" xmlns:mvc="http://www.springframework.org/schema/mvc" xmlns:p="http://www.springframework.org/schema/p" xmlns:aop="http://www.springframework.org/schema/aop" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:context="http://www.springframework.org/schema/context" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd http://www.springframework.org/schema/mvc http://www.springframework.org/schema/mvc/spring-mvc.xsd http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop.xsd http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context.xsd"> <mvc:annotation-driven/> <bean class="org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter"> <property name="messageConverters"> <list> <bean class="com.rocky.api.spring.MappingFastjsonHttpMessageConverter"> <property name="supportedMediaTypes"> <list> <value>text/plain;charset=UTF-8</value> <value>application/json;charset=UTF-8</value> </list> </property> </bean> </list> </property> </bean> <!-- 扫描controller --> <context:component-scan base-package="com.rocky.api.controller"/> <!-- 对模型视图名称的解析，即在模型视图名称添加前后缀 --> <bean class="org.springframework.web.servlet.view.InternalResourceViewResolver" p:prefix="/WEB-INF/view/" p:suffix=".jsp" /> <mvc:interceptors> <!-- 性能拦截器 --> <mvc:interceptor> <mvc:mapping path="/**"/> <mvc:exclude-mapping path="/static/**"/> <bean class="com.rocky.common.aop.PerformanceInterceptor"/> </mvc:interceptor> </mvc:interceptors> <mvc:resources location="/resources/" mapping="/resources/**"/> <aop:aspectj-autoproxy proxy-target-class="true"/> <bean class="com.rocky.api.advice.ControllerExecutionTime"/> </beans>
2.2 引入jar包
<!-- perf4j --> <dependency> <groupId>org.perf4j</groupId> <artifactId>perf4j</artifactId> <version>${perf4j.version}</version> </dependency>
2.3 切面
import com.rocky.common.utils.NetworkUtil; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.Signature; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.annotation.Pointcut; import org.aspectj.lang.reflect.CodeSignature; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.web.context.request.RequestContextHolder; import org.springframework.web.context.request.ServletRequestAttributes; import javax.servlet.http.HttpServletRequest; @Aspect public class ControllerExecutionTime { private static final Logger logger = LoggerFactory.getLogger(ControllerExecutionTime.class); @Pointcut(value = "@annotation(org.springframework.web.bind.annotation.RequestMapping)") public void requestMappingMethod(){ } @Around("requestMappingMethod()") public Object aroundControllerAdvice(ProceedingJoinPoint joinPoint)throws Throwable{ return executeTimeLog(joinPoint); } private Object executeTimeLog(ProceedingJoinPoint joinPoint) throws Throwable { long begin = System.currentTimeMillis(); Signature sig = joinPoint.getSignature(); String className = sig.getDeclaringType().getName(); String method = sig.getName(); StringBuffer stringBuffer = new StringBuffer(); Object[] argsArray = joinPoint.getArgs(); String[] parameterNamesArray = ((CodeSignature)joinPoint.getStaticPart().getSignature()).getParameterNames(); for (int i = 0; i < argsArray.length; i++) { stringBuffer.append(parameterNamesArray[i] + ":" + argsArray[i]); if(i < argsArray.length - 1) stringBuffer.append(","); } if(argsArray.length > 0){ logger.info("{} - begin, " + stringBuffer.toString(), method); } try { Object result = joinPoint.proceed(argsArray); if(result != null) { logger.info("{} - end, result:" + result.toString(), method); } return result; } finally { long end = System.currentTimeMillis(); float execTime = (end - begin); //logger.info(String.format("[%s#%s] Executed %f ms.", className, method, execTime)); //class_name,method,exectime,server_host,client_host HttpServletRequest request = getRequest(); logger.info("{} - Executed {} ms, server host is {}, remote ip is {}", method, execTime, NetworkUtil.getServerHost(request), NetworkUtil.getRemoteIP(request)); } } private HttpServletRequest getRequest() { return (RequestContextHolder.getRequestAttributes() == null) ? null : ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest(); } }
2.4 拦截器
package com.rocky.common.aop; import com.rocky.common.utils.IpUtil; import org.perf4j.StopWatch; import org.perf4j.slf4j.Slf4JStopWatch; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.slf4j.MDC; import org.springframework.web.servlet.HandlerMapping; import org.springframework.web.servlet.handler.HandlerInterceptorAdapter; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import java.util.UUID; /** * @author sxf * */ public class PerformanceInterceptor extends HandlerInterceptorAdapter { private static ThreadLocal<StopWatch> local = new ThreadLocal<>(); /** * 追踪ID */ private final static String TRACE_KEY = "traceId"; private final Logger switchLogger = LoggerFactory.getLogger("org.perf4j.TimingLogger"); @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { StopWatch stopWatch = new Slf4JStopWatch("shell"); local.set(stopWatch); MDC.put(TRACE_KEY, UUID.randomUUID().toString().replace("-", "")); return true; } @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { StopWatch watch = local.get(); if (watch != null) { watch.stop(generateOperatonIdendifier(request, watch.getElapsedTime())); local.remove(); } MDC.remove(TRACE_KEY); } private String generateOperatonIdendifier(HttpServletRequest request, long exeTime) { StringBuilder sb = new StringBuilder(64); sb.append(request.getMethod()).append("|"); // URI if (switchLogger.isTraceEnabled()) { // 如果是trace级别，统计到具体的URI sb.append(request.getRequestURL()); sb.append('|'); String clientIp = IpUtil.getIp(request); sb.append(clientIp); sb.append('|'); sb.append(request.getHeader("User-Agent")); } else { // 按URI pattern匹配，方便汇总 sb.append(request.getAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE)); } // 记录慢得url, if (exeTime > 100) { sb.append("|SLOW"); } return sb.toString(); } }
2.5 logback 增加 日志输出 及 traceID输出(以区分不同请求)
<?xml version="1.0" encoding="UTF-8"?> <configuration scan="false" scanPeriod="1 minutes" debug="true"> <property name="LOG_HOME" value="/rocky/logs"/> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender" additivity="false"> <encoder> <pattern>%d{yyyy-MM-dd.HH:mm:ss.SSS} %t %p %c{0} %X{traceId} : %m%n</pattern> </encoder> </appender> <appender name="DETAIL" class="ch.qos.logback.core.rolling.RollingFileAppender" additivity="false"> <file>${LOG_HOME}/integral-detail-${port}.log</file> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <FileNamePattern>${LOG_HOME}/integral-detail-${port}.log.%d{yyyy-MM-dd}</FileNamePattern> <MaxHistory>90</MaxHistory> </rollingPolicy> <encoder> <pattern>%d{yyyy-MM-dd.HH:mm:ss.SSS} %t %p %c{0} %X{traceId} : %m%n</pattern> <charset>UTF-8</charset> </encoder> </appender> <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender" additivity="false"> <file>${LOG_HOME}/integral-error-${port}.log</file> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>ERROR</level> </filter> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <FileNamePattern>${LOG_HOME}/integral-error-${port}.log.%d{yyyy-MM-dd}</FileNamePattern> <MaxHistory>90</MaxHistory> </rollingPolicy> <encoder> <pattern>%d{yyyy-MM-dd.HH:mm:ss.SSS} %t %p %c{0} %X{traceId} : %m%n</pattern> <charset>UTF-8</charset> </encoder> </appender> <appender name="perf4jFile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${LOG_HOME}/integral-api-perf4j-${port}.log</file><!--${catalina.home}--> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <FileNamePattern>${LOG_HOME}/integral-api-perf4j-${port}.log.%d{yyyyMMdd}</FileNamePattern> <MaxHistory>20</MaxHistory> </rollingPolicy> <encoder> <pattern>%date [%thread] %-5level %F{16} [%M:%L] - %msg%n</pattern> <charset>utf-8</charset> </encoder> </appender> <appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender"> <param name="TimeSlice" value="60000"/> <appender-ref ref="perf4jFile"/> </appender> <logger name="org.perf4j.TimingLogger" level="info" additivity="false"> <appender-ref ref="CoalescingStatistics"/> </logger> <root level="INFO" additivity="true"> <appender-ref ref="DETAIL"/> <appender-ref ref="ERROR"/> </root> <!-- #模式符号 - 用途(附加说明);{可选附加选项}(附加选项说明) # %c - 日志名称(通常是构造函数的参数);{数字}("a.b.c" 的名称使用 %c{2} 会输出 "b.c") # %C - 调用者的类名(速度慢,不推荐使用);{数字}(同上) # %d - 日志时间;{SimpleDateFormat所能使用的格式} # %F - 调用者的文件名(速度极慢,不推荐使用) # %l - 调用者的函数名、文件名、行号(速度极其极其慢,不推荐使用) # %L - 调用者的行号(速度极慢,不推荐使用) # %m - 日志 # %M - 调用者的函数名(速度极慢,不推荐使用) # %n - 换行符号 # %p - 日志优先级别(DEBUG, INFO, WARN, ERROR) # %r - 输出日志所用毫秒数 # %t - 调用者的进程名 # %x - Used to output the NDC (nested diagnostic context) associated with the thread that generated the logging event. # %X - Used to output the MDC (mapped diagnostic context) associated with the thread that generated the logging event. # #模式修饰符 - 对齐 - 最小长度 - 最大长度 - 说明 # %20c 右 20 ~ # %-20c 左 20 ~ # %.30c ~ ~ 30 # %20.30c 右 20 30 # %-20.30c 左 20 30 --> </configuration>
2.6 工具类
package com.rocky.common.utils; import javax.servlet.http.HttpServletRequest; import java.net.Inet4Address; import java.net.InetAddress; import java.net.NetworkInterface; import java.net.SocketException; import java.util.ArrayList; import java.util.Collection; import java.util.Enumeration; import java.util.List; import java.util.regex.Pattern; public class IpUtil { /** * 取客户端的真实ip，考虑了反向代理等因素的干扰 */ public static String getIp(HttpServletRequest request) { String xff = request.getHeader("X-Forwarded-For"); String ip = resolveClientIPFromXFF(xff); if (isValidIP(ip)) { return ip; } ip = request.getHeader("Proxy-Client-IP"); if (isValidIP(ip)) { return ip; } ip = request.getHeader("WL-Proxy-Client-IP"); if (isValidIP(ip)) { return ip; } return request.getRemoteAddr(); } /** * 从X-Forwarded-For头部中获取客户端的真实IP。 * X-Forwarded-For并不是RFC定义的标准HTTP请求Header，可以参考http://en.wikipedia.org/wiki/X-Forwarded-For * * @param xff X-Forwarded-For头部的值 * @return 如果能够解析到client IP，则返回表示该IP的字符串，否则返回null */ private static String resolveClientIPFromXFF(String xff) { if (xff == null || xff.length() == 0) { return null; } String[] ss = xff.split(","); for (String ip : ss) { ip = ip.trim(); if (isValidIP(ip)) return ip; } return null; } // long ip to string public static String iplongToIp(long ipaddress) { StringBuffer sb = new StringBuffer(""); sb.append(String.valueOf((ipaddress >>> 24))); sb.append("."); sb.append(String.valueOf((ipaddress & 0x00FFFFFF) >>> 16)); sb.append("."); sb.append(String.valueOf((ipaddress & 0x0000FFFF) >>> 8)); sb.append("."); sb.append(String.valueOf((ipaddress & 0x000000FF))); return sb.toString(); } //string ip to long public static long ipStrToLong(String ipaddress) { long[] ip = new long[4]; int position1 = ipaddress.indexOf("."); int position2 = ipaddress.indexOf(".", position1 + 1); int position3 = ipaddress.indexOf(".", position2 + 1); ip[0] = Long.parseLong(ipaddress.substring(0, position1)); ip[1] = Long.parseLong(ipaddress.substring(position1 + 1, position2)); ip[2] = Long.parseLong(ipaddress.substring(position2 + 1, position3)); ip[3] = Long.parseLong(ipaddress.substring(position3 + 1)); return (ip[0] << 24) + (ip[1] << 16) + (ip[2] << 8) + ip[3]; } /** * 检查是否是一个合格的ipv4 ip * * @param ip * @return */ public static boolean isValidIP(String ip) { if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) return false; return ipPattern.matcher(ip).matches(); } /** * 取得一个合格的ipv4 ip,外网ip * * @return */ public static String getLocalIP() { for (String a : getAllNoLoopbackAddresses()) { if (isValidIP(a)) { return a; } } return ""; } /** * 获取本地地址 * 内网ip * * @return 本机ipv4地址 */ public static final String getLocalAddress() { try { for (Enumeration<NetworkInterface> ni = NetworkInterface.getNetworkInterfaces(); ni.hasMoreElements(); ) { NetworkInterface eth = ni.nextElement(); for (Enumeration<InetAddress> add = eth.getInetAddresses(); add.hasMoreElements(); ) { InetAddress i = add.nextElement(); if (i instanceof Inet4Address) { if (i.isSiteLocalAddress()) { return i.getHostAddress(); } } } } } catch (SocketException e) { e.printStackTrace(); } return ""; } /** * 取得本地所有的ipv4列表 * * @return */ public static List<String> getLocalIPs() { List<String> localIps = new ArrayList<String>(); for (String a : getAllNoLoopbackAddresses()) { if (isValidIP(a)) { localIps.add(a); } } return localIps; } private static final Pattern ipPattern = Pattern.compile("([0-9]{1,3}\\.){3}[0-9]{1,3}"); private static Collection<InetAddress> getAllHostAddress() { try { Enumeration<NetworkInterface> networkInterfaces = NetworkInterface.getNetworkInterfaces(); Collection<InetAddress> addresses = new ArrayList<InetAddress>(); while (networkInterfaces.hasMoreElements()) { NetworkInterface networkInterface = networkInterfaces.nextElement(); Enumeration<InetAddress> inetAddresses = networkInterface.getInetAddresses(); while (inetAddresses.hasMoreElements()) { InetAddress inetAddress = inetAddresses.nextElement(); addresses.add(inetAddress); } } return addresses; } catch (Exception e) { e.printStackTrace(); } return null; } private static Collection<String> getAllNoLoopbackAddresses() { Collection<String> noLoopbackAddresses = new ArrayList<String>(); Collection<InetAddress> allInetAddresses = getAllHostAddress(); for (InetAddress address : allInetAddresses) { if (!address.isLoopbackAddress()) { noLoopbackAddresses.add(address.getHostAddress()); } } return noLoopbackAddresses; } }
2.7 效果
详细日志 有traceid 方便过滤
统计日志
