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 方便过滤

统计日志