高并发场景下，Java 日志的最佳应用实践

作者: 码自在 | 来源:发表于2020-05-04 18:27 被阅读0次

日志技术选型

Log 门面层选型

《阿里巴巴 Java 开发规范》【强制】应用中不可使用日志系统（Log4J、Logback）中的 API，而应依赖使用日志框架 SLF4J 中的 API。使用门面模式的日志框架，有利于维护和各个类的日志处理方式统一。

上面所说的是阿里 Java 开发规范中的规则，应用必须使用门面模式的日志框架，首选我们回顾一下门面设计模式。
门面模式，又叫外观模式，它为子系统中的一组接口提供一个统一的高层接口，使的子系统更容易使用。使用门面模式的优点是：

解耦，通过统一对外的接口，屏蔽了与子系统的依赖和子系统的复杂性。
提高了灵活性，子系统内部的变化，只要不影响到门面对象，任其变化。其结构见下图。

image.png

通过上面的回顾，我们也了解了门面设计模式。应用使用门面模式的日志框架，可以部署时，根据需要切换不同的日志框架。Java 中有哪些门面模式的日志框架呢？常见的有 Apache Common-Logging、SLF4J。
Commons Logging 实现机制：

Apache Common-Logging 使用了 ClassLoader 寻找和载入底层的日志库，存在一定加载问题。

SLF4J 实现机制：

SLF4J 在编译期间，静态绑定本地的 Log 库。它是通过查找类路径下 org.slf4j.impl.StaticLoggerBinder，然后在 StaticLoggerBinder 中进行绑定。使用 SLF4J 时，需要指定具体的日志器实现，常用的 Log4j、Log4j2、Logback、JDK-logging、SLF4J-simple 都可以实现，对于不同的日志实现方案，封装出不同的桥接组件。下图是 SLF4J 与各组件 API 打通的的相关方案。

image.png

门面框架的选择：

考虑到 SLF4J 的广泛通用性及静态编译支持，门面层使用 SLF4J 作为日志 API 层选型。

日志引擎层技术选型

下图是各个日志框架性能测试如下（来自 Log4j2 官方网站）：

image.png

下图是 garbage-free async loggers （无垃圾异步模式）在测试的所有配置中都具有最佳响应 time 行为。

image.png
根据以上数据显示，Log4j2 通过异步化支持及队列的使用使性能得到的极大的提升。这是如何工作的，应用线程完成了最少量的工作来捕获 log event 中的所有必需信息，然后将此 log event 放在队列中以供后续线程稍后处理。如果队列的大小足够大，那么应用线程应该能够在 logging 调用上花费很少的 time，并且非常快速地返回到业务逻辑。

事实证明，队列的选择对于峰值吞吐量非常重要。 Log4j2 的 Async Loggers 使用无锁数据结构（Disruptor），而 Logback、Log4j 1.2 和 Log4j2 的异步 Appenders 使用 ArrayBlockingQueue。使用阻塞队列时，对线程应用在尝试将 log event 排入队列时经常会遇到锁争用。所以 Log4j2 的 Async Loggers 在一定程度上提供更好的吞吐量，但是一旦队列已满，appender 线程需要等待，直到队列中的一个插槽可用，并且吞吐量将降至最大最好的基础 appenders 的持续吞吐量。

并且 Log4j2 改版以后，组件和功能极大丰富，有兴趣的同学可以去官网：

http://logging.apache.org/log4j/2.x/manual/index.html

日志引擎框架的选择：

经过上述的分析，所以在日志引擎层毫无疑问选用 Log4j2 是最佳选择。

Log4j2 简介

关于 Log4j2

Apache Log4j 2 是 Log4j 1 的继任者，2014 年 7 月其 GA 版本（正式发布版）发布。该框架被从头重写，并从现有的日志解决方案中获得灵感（包括 Log4j 1 和 JUL）。该版本与 Log4j 1 的主要差异是：

改进的配置语法。
支持 XML 和 JSON 配置。
改进的过滤器。
属性（Property）支持。
标记。
提高速度。
模块化，Log4j 2 支持插件系统。
提高了可靠性。
配置自动重装。
Log4j 2 的最被认可的特点之一是“异步记录器”的性能。Log4j 2 利用了 LMAX Disruptor。例如，在相同的环- 境下，Log4j 2 可以写每秒超过 18,000,000 条信息，而其他框架（像 Logback 和 Log4j 1）每秒只能写< 2,000,000 条消息。
Log4j 2 提供对 SLF4J、Commons Logging、Apache Flume 和 Log4j 1 的支持。

异步 Loggers

异步是 Log4j2 最大的亮点，性能提升的关键，应用无锁模式（Disruptor）实现。在实践中，官方推荐使用 Async Logger 的全异步方式，进行异步日志的配置。唯一的缺点就是如果异常可能不能通知给应用程序，这一点根据实际情况处理。

Garbage-free Logging

许多 logging libraries，包括以前版本的 Log4j，在稳定 state logging 期间分配临时 objects，如 log event objects、Strings、char 数组、字节数组等。这会对垃圾收集器造成压力并增加 GC 暂停发生的频率。

从 version 2.6 开始，默认情况下 Log4j 以“无垃圾”模式运行，其中重复使用 objects 和 buffers，并且尽可能不分配临时 objects，原理是通过 ThreadLocal 实现复用。

Spring Boot 集成 Log4j2

Maven 配置

首先剔除 Spring Boot 自带的 Logback 配置、加入 Log4j2 starter 和异步依赖的 disruptor 配置。

  <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>
        <!--log4j2 异步依赖-->
        <dependency>
            <groupId>com.lmax</groupId>
            <artifactId>disruptor</artifactId>
            <version>3.4.2</version>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>

        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>fastjson</artifactId>
            <version>1.2.68</version>
        </dependency>

日志格式很重要，在微服务中，经常会用到 elk 等组件来收集日志，统一查询。为了方便查找问题，定位问题，我们实践中最佳的输出格式如下：

[机器 IP 地址] | [线程 ID] | [微服务名] | [时间] | [日志级别] | [包名] | [日志信息]

数据项	收集方式	配置方式
机器 IP 地址	在应用启动时通过 MDC 注入本机 IP 如：MDC.put("ip", "129.12.31.1");	%X{ip}
线程 ID	日志组件自动收集	%t
微服务名	在应用启动时通过 MDC 注入服务名如：MDC.put("serverName",”user-center“);	%X{serverName}
时间	组件自动收集	%d{yyyy-MM-dd HH:mm:ss,SSS}
日志级别	配置	%p
包名	组件自动收集	%c
日志信息	程序输出如：log.info()	%m

Log4j2 配置文件在 resource 下生成 log4j2.xml。
内容如下，实际使用中根据情况修改：

<?xml version="1.0" encoding="UTF-8"?>
<!--日志级别以及优先级排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL -->
<!--status="WARN" :用于设置 log4j2 自身内部日志的信息输出级别，默认是 OFF-->
<!--monitorInterval="30"  :间隔秒数,自动检测配置文件的变更和重新配置本身-->
<configuration status="WARN" monitorInterval="60" strict="true">
    <properties>
        <!--自定义一些常量，之后使用${变量名}引用-->
        <property name="logPath">./logs</property>
        <property name="charset">UTF-8</property>
        <!--自定义的输出格式-->
        <property name="pattern">%X{ip}|%t|%X{serverName}|%d{yyyy-MM-dd HH:mm:ss,SSS}|%p|%c|%m%n</property>
    </properties>
    <!--appenders:定义输出内容,输出格式,输出方式,日志保存策略等,常用其下三种标签[console,File,RollingFile]-->
    <!--Appender 可以理解为日志的输出目的地-->
    <appenders>

        <!--console :控制台输出的配置-->
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="${pattern}" charset="${charset}"/>
        </Console>

        <!--RollingRandomAccessFile 性能比 RollingFile 提升官网宣称是 20-200%-->
        <RollingRandomAccessFile name="DEMO.ERROR" immediateFlush="true" bufferSize="4096"
                                 fileName="${logPath}/error.log"
                                 filePattern="${logPath}/error.%d{yyyy-MM-dd}.gz"
                                 ignoreExceptions="false">
            <PatternLayout pattern="${pattern}" charset="${charset}"/>
            <Filters>
                <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
                <SizeBasedTriggeringPolicy size="500MB"/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="${logPath}" maxDepth="2" followLinks="true">
                    <IfFileName glob="error.*.gz"/>
                    <IfLastModified age="7d"/>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingRandomAccessFile>

        <RollingRandomAccessFile name="DEMO.WARN" immediateFlush="false" bufferSize="4096"
                                 fileName="${logPath}/warn.log"
                                 filePattern="${logPath}/warn.%d{yyyy-MM-dd}-%i.gz"
                                 ignoreExceptions="false">
            <PatternLayout pattern="${pattern}" charset="${charset}"/>
            <Filters>
                <!--ThresholdFilter :日志输出过滤-->
                <ThresholdFilter level="WARN" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
                <SizeBasedTriggeringPolicy size="500MB"/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="${logPath}" maxDepth="2" followLinks="true">
                    <IfFileName glob="warn.*.gz"/>
                    <IfLastModified age="7d"/>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingRandomAccessFile>

        <RollingRandomAccessFile name="DEMO.INFO" immediateFlush="true"
                                 fileName="${logPath}/info.log"
                                 filePattern="${logPath}/info.%d{yyyy-MM-dd}-%i.gz"
                                 ignoreExceptions="false">
            <PatternLayout pattern="${pattern}" charset="${charset}"/>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
                <SizeBasedTriggeringPolicy size="500MB"/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="${logPath}" maxDepth="2" followLinks="true">
                    <IfFileName glob="info.*.gz"/>
                    <IfLastModified age="7d"/>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingRandomAccessFile>

    </appenders>

    <!--然后定义 logger，只有定义了 logger 并引入的 appender，appender 才会生效-->
    <loggers>
        <Logger additivity="true" name="com.example" level="INFO">
        </Logger>
        <!-- Root 节点用来指定项目的根日志，如果没有单独指定 Logger，那么就会默认使用该 Root 日志输出 -->
        <Root level="INFO" includeLocation="true">
            <AppenderRef ref="console"/>
            <AppenderRef ref="DEMO.INFO"/>
            <AppenderRef ref="DEMO.ERROR"/>
            <AppenderRef ref="DEMO.WARN"/>
        </Root>
    </loggers>
</configuration>

然后在 application.properties 指定 Log4j2 的配置文件，如下：

logging.config=classpath:log4j2.xml

配置日志为全异步方式，在 resource 下创建 log4j2.component.properties 文件，内容如下，开启全异步模式：

Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

配置文件结构如下图：

image.png

主程序通过 MDC 方式注入 IP 和 serverName：

public class DemoApplication {
    public static void main(String[] args) {
        initMainThreadLogProperties();
        SpringApplication.run(DemoApplication.class, args);
    }

    private static void initMainThreadLogProperties() {
        PropertiesUtil propertiesUtil;
        try {
            propertiesUtil = new PropertiesUtil("application.properties");
            MDC.put("ip", getLocalIp());
            MDC.put("serverName", getServerName());
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

业务线程通过 Filter 的方式注入 IP 和 serverName：

@Order(1)
@WebFilter(filterName = "logFilter", urlPatterns = "/*")
public class LogFilter implements Filter {

    @Value("${spring.application.name}")
    private String serverName;

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        HttpServletRequest request = (HttpServletRequest) servletRequest;
        MDC.put("ip", request.getLocalAddr());
        MDC.put("serverName", serverName);
        filterChain.doFilter(servletRequest, servletResponse);
    }
}

通过 AOP 打印入参、出参、和接口耗时信息：

@Aspect
@Order(5)
@Component
@Slf4j
public class LogAspect {

    @Pointcut("execution(public * com.example.demo.controller..*(..))")
    public void weblog() {
    }

    /**
     * 请求执行过程 记录 ip、入参、出参、耗时
     *
     * @param joinPoint
     */
    @Around("weblog()")
    public Object aroundAdvice(ProceedingJoinPoint joinPoint) throws Throwable {
        Object[] args = joinPoint.getArgs();
        HttpServletRequest request = getRequestContext();

        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        try {
            Object result = joinPoint.proceed(args);
            stopWatch.stop();
            if (log.isInfoEnabled()) {
                log.info("client_ip={},url={} ,cost_time={}ms,args={},result={}", request.getRemoteAddr(),
                        request.getRequestURL().toString(), stopWatch.getTotalTimeMillis(), JSON.toJSONString(args), JSON.toJSONString(result));
            }
            return result;
        } catch (Throwable e) {
            log.error("client_ip={},url={} ,cost_time={}ms,,args={}", request.getRemoteAddr(),
                    request.getRequestURL().toString(), stopWatch.getTotalTimeMillis(), JSON.toJSONString(args), e);
            throw e;
        }
    }

    /**
     * 获取 HttpServletRequest
     *
     * @return
     */
    private HttpServletRequest getRequestContext() {
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        return request;
    }
}

以上就是日志集成的一个最佳实践，我把具体的 Demo 上传到 GitHub 上了，感兴趣的朋友可以下载下来，里面的 Demo 都可以直接运行，Demo 里还包括接口统一异常处理和日志打印的处理。地址：

https://github.com/zhaoyueoop/springboot-log4j2-demo

高并发场景下

日志打印的的正确姿势

// 传统的字符串产生方式，如果没有要记录 Debug 等级的信息，就会浪费时间在产生不必要的信息上
logger.debug("There are now " + count + " user accounts: " + userAccountList);

// 为了避免上述问题，我们可以先检查是不是开启了 Debug 信息记录功能，只是程序的编码会比较复杂
if (logger.isDebugEnabled()) {
    logger.debug("There are now " + count + " user accounts: " + userAccountList);
}

//应用占位符的方式， 如果 Debug 等级没有开启，则不会产生不必要的字符串，同时也能保持程序编码的简洁
logger.debug("There are now {} user accounts: {}", count, userAccountList);

如上述第一行代码，如果日志级别是 WARN 级别，虽然 logger.debug 不会输出日志，但还会进行字符串拼接，并发量大的时候存在性能问题。为了避免这个问题可以先检查是否开启了 Debug 级别，可以通过这个 logger.isDebugEnabled() 方法，但这样会使编码比较复杂，代码不够简洁。在这里推荐上述代码中的第三中方式，占位符方式，这种方式即使没有开启 Debug 登记，也不会产生不必要的字符串拼接等操作，也能保持代码的简洁性。

高并发场景下，一定要用异步和缓冲模式来打印日志，同步方式会造成大量系统文件 IO 操作，导致应用并发上不去，甚至挂掉。记得多年前，当时配置日志，只会从网上 copy 一份修改一下，里面的参数并不清楚是什么作用，不知道读者是不是也会这样。所以配置日志的时候，一定要非常清楚各个参数的意义，如果不清楚，建议去官方看一看。

分布式系统日志链路跟踪方案与原理

随着系统的微服务化，一次业务接口的调用可能需要多个微服务间协同调用来完成。那如何直观的了解系统的调用及运行情况呢。可以在业务日志中增加调用链 ID, 把业务日志和调用链关联起来，可以方便查看一次业务接口调用相关的所有日志信息，方便定位问题。

如何在日志中埋入调用链 ID 呢？

两种方式，一是客户端发送请求时生成调用链 Id（TraceId），二是服务端调用的首节点负责生成。生成方式可以通过 UUID 等方式。然后通过线程上下文（ThreadLocal）传递 TraceId，跨节点时，通过 RPC 框架或 HTTP 通过传参显示的传到下一节点。

如果使用 MQ 异步操作时怎么办呢？

各位小伙伴可以自己想一想。这是我们自己实现日志追踪的方案，有些代码的侵入，那有没有更方便的呢？答案肯定是有的，那就是 JavaAgent 技术，如阿里开源的 SkyWalking 分布式追踪系统，通过动态字节码技术，无侵入的实现服务之间的追踪，并提供 UI 界面查看调用链情况，非常方便，感兴趣的可以深入研究。

结束语

希望上述写的，能在实际项目中帮到你，感兴趣的可以深入了解日志中应用到的技术，我在结尾附上，我觉得写的不错的博客，大家也可以去看一看。欢迎留言讨论。

关于 Disruptor：

https://tech.meituan.com/2016/11/18/disruptor.html

关于 MDC：

https://ketao1989.github.io/2015/04/29/LogBack-Implemention-And-Slf4j-Mdc/

关于 ThreadLocal：

https://juejin.im/post/5ac2eb52518825555e5e06ee

关于 SkyWalking：

https://skywalking.apache.org/zh/

高并发场景下，Java 日志的最佳应用实践

日志技术选型

Log 门面层选型

日志引擎层技术选型

Log4j2 简介

关于 Log4j2

异步 Loggers

Garbage-free Logging

Spring Boot 集成 Log4j2

高并发场景下

日志打印的的正确姿势

分布式系统日志链路跟踪方案与原理

结束语

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读