【日志】logback 耗时性能监控与使用

【日志】logback 耗时性能监控与使用

背景

• 随着代码的开发完毕与项目的测试结束,需要对代码进行性能测试,需要知道方法的调用时长,但是这样就需要去代码里写耗时代码,而此博客就简便的开发人员的使用,使用logback与aop现实代码的耗时监控

最终效果

• tag: 类的全限定名与调用方法名
• avg: 时间范围内调动的平均时长
• min: 时间范围内最小时长
• max: 时间范围内最大时长
• std dev: 标准差
• count: 时间范围内调用次数

配置

引入jar包

 implementation 'org.perf4j:perf4j:0.9.16'
 implementation 'org.springframework.boot:spring-boot-starter-aop'

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<!--
   logback日志配置
-->
<configuration debug="false">

    <!--获取spring上下文配置-->
    <springProperty scope="context" name="SERVER_NAME" source="server.servlet.application-display-name"/>
    <springProperty scope="context" name="LOG_ROOT_LEVEL" source="logging.level.root"/>
    <!--定义日志文件的存储地址及日志级别 勿在 LogBack 的配置中使用相对路径-->
    <property name="LOG_HOME" value="${sys:catalina.base:-.}/output/logs"/>
    <!-- pattern -->
    <property name="CONSOLE_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5le) [%11(%.11t)] %cyan(%-50(%lo{50})) - %m%n"/>
    <property name="FILE_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5le [%15(%.15t)] %-60(%lo{60}) - %m%n"/>
    <!-- 控制台输出 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
            <pattern>${CONSOLE_PATTERN}</pattern>
        </encoder>
    </appender>
    <!-- 按照每天生成日志文件 INFO-->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <!--日志文件输出的文件名-->
            <FileNamePattern>${LOG_HOME}/${SERVER_NAME}.%d{yyyy-MM-dd}.%i.log</FileNamePattern>
            <!--日志文件保留天数-->
            <MaxHistory>15</MaxHistory>
            <!--给定日志文件大小，超过指定的大小就新建一个日志文件-->
            <maxFileSize>100MB</maxFileSize>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
            <pattern>${FILE_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- 按照每天生成日志文件 ERROR -->
    <appender name="FILE_ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>  <!-- 如果没有命中就使用这条规则 -->
            <onMismatch>DENY</onMismatch>  <!-- 如果命中就禁止这条日志  -->
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <!--日志文件输出的文件名-->
            <FileNamePattern>${LOG_HOME}/dev/${SERVER_NAME}.%d{yyyy-MM-dd}.%i.log</FileNamePattern>
            <!--日志文件保留天数-->
            <MaxHistory>15</MaxHistory>
            <!--给定日志文件大小，超过指定的大小就新建一个日志文件-->
            <maxFileSize>100MB</maxFileSize>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
            <pattern>${FILE_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- 生成耗时性能日志文件 -->
    <appender name="statFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/time/${SERVER_NAME}.%d{yyyy-MM-dd}.log</FileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %d{yyyy-MM-dd HH:mm:ss} %-5level %logger{36} - %msg%n
            </Pattern>
        </layout>
    </appender>

    <!-- 多环境配置 按照active profile选择分支 -->
    <springProfile name="dev">
        <!--root节点 全局日志级别，用来指定最基础的日志输出级别-->
        <root level="${LOG_ROOT_LEVEL}">
            <appender-ref ref="STDOUT"/>
        </root>
        <!--异步生成性能配置文件-->
        <appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
            <!-- TimeSlice配置多少时间间隔去做一次汇总写入文件中 默认值是 30000 ms -->
            <timeSlice>10000</timeSlice>
            <appender-ref ref="statFileAppender"/>
        </appender>
        <!-- 性能日志输出级别 name与切面的配置一致 -->
        <logger name="org.perf4j.TimingLogger" level="info" additivity="false">
            <appender-ref ref="CoalescingStatistics"/>
        </logger>
    </springProfile>

    <springProfile name="test|prod">
        <!--root节点 全局日志级别，用来指定最基础的日志输出级别-->
        <root level="${LOG_ROOT_LEVEL}">
            <appender-ref ref="FILE"/>
            <appender-ref ref="FILE_ERROR"/>
        </root>
    </springProfile>
</configuration>

切面注解

import java.lang.annotation.*;

/**
 * 日志监控注解
 *
 * @author bo.huang update
 * @date 2020/4/21 2:43 下午
 */
@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface Perf4Log {

}

切面类

package com.emodernhy.generator.config.log;

import lombok.extern.java.Log;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.perf4j.StopWatch;
import org.perf4j.commonslog.CommonsLogStopWatch;
import org.springframework.stereotype.Component;

/**
 * 日志性能监控切面
 *
 * @author bo.huang update
 * @date 2020/4/21 1:52 下午
 */
@Aspect
@Component
@Log
public class Perf4jLogAspect {

    /**
     * 与logback-spring.xml 中  <logger name="org.perf4j.TimingLogger" level="info" additivity="false">name 一致
     */
    private static final String STOP_WATCH_LOGGER_NAME = "org.perf4j.TimingLogger";

    /**
     * 切入点
     * 默认以注解为切入点,如果execution
     * execution(public * com.emodernhy.generator.controller..*.*(..))||execution(public * com.emodernhy.generator.service..*.*(..))
     *
     * @author bo.huang update
     * @date 2020/4/21 2:59 下午
     */
    @Pointcut("@annotation(com.emodernhy.generator.config.log.Perf4Log))")
    public void pointcut() {
    }

    /**
     * 切面,把信息放入
     *
     * @param point point
     * @return java.lang.Object
     * @author bo.huang update
     * @date 2020/4/21 3:01 下午
     */
    @Around("pointcut()")
    public Object logPer4jLogs(ProceedingJoinPoint point) throws Throwable {
        String className = point.getSignature().getDeclaringTypeName();
        String methodName = point.getSignature().getName();
        String name = className + "." + methodName;
        StopWatch stopwatch = new CommonsLogStopWatch(STOP_WATCH_LOGGER_NAME);
        final Object returnValue = point.proceed();
        stopwatch.stop(name);
        return returnValue;
    }

}

使用

测试方法上配置注解@Perf4Log

• 注意:日志配置是10S,异步写入文件,不会实时写入