浅析JAVA日志中的几则性能实践与原理解释

Logger logger = LogFactory.getLogger("PoweredByEDAS");
String product = "EDAS";logger.info("This is powered by product: " + product);

这一篇文章是想通过几个技术点来说明日志记录过程中的性能实践，计算机领域的性能往往都遵循着冰山法则，即你能看得见的、程序员能感知的只是其中的一小部分，还有大量的细节隐藏在冰山之下，如下图所示：

<Appenders>  <CountingNoOp name="NoOp">  </CountingNoOp></Appenders>

1. 与只写入内存的吞吐量相比，二者的吞吐量随着日志内容的变大差距越来越大。

2. 同时随着输出内容的数量变多，在磁盘场景下呈现明显的下滑趋势，随着内容的增多，呈现逐渐趋平的趋势。

压缩Logger输出：

package com.alibabacloud.edas.demo;
public class PoweredByEdas {  private static Logger logger = LogFactory.getLogger(        ProweredByEdas.class);
    public void execute() {        String product = "EDAS";         logger.info("Prowered by " + product);    }}

而在进行日志输出时，如果 logger 是 Class 将默认输出对应它所对应的 FQCN，即：com.alibabacloud.edas.demo.PoweredByEdas

// 使用默认 [%logger] 进行输出2023-11-11 16:14:36.790 INFO [com.alibabacloud.edas.demo.PoweredByEdas] Prowered by EDAS 
// 使用默认 [%logger{5}] 进行输出2023-11-11 16:24:44.879 INFO [c.a.e.d.PoweredByEdas] Prowered by EDAS

不过这种日志处理由于做字符串的拆分和截取，会额外耗费一定的 CPU，如果是计算密集型的业务（CPU 占用本来就很高的情况下）则不建议生产使用。

压缩异常输出

1. 保留栈顶的几帧：栈顶往往包含的是最为关键的信息，是案发的第一现场，他的信息完整性显得尤为重要。

2. 保留业务栈帧：在 Java 语言中，大家会遵循给业务代码一个单独包名的实践，此时我们可以利用包名进行栈帧的过滤和保留操作。

3. 抽样打印全栈信息：这里可以根据具体的业务情况而定，需要将全栈信息进行随机输出的原因是有的时候可能会追踪到一些系统级别的 BUG 或想了解他的一些机制。全栈信息的输出有助于问题的追根溯源。

1. 在进行日志内容写入时，通过异步缓冲区解耦业务代码到通道(从日志框架 到 JVM 到 操作系统 FileSystem）的瓶颈。

2. 在进行文件内容落盘时，通过大文件切分成小文件的方式，尽量解耦硬件级别的瓶颈。

使用异步日志

1. Log4j2 AsyncAppender

• shutdownTimeout：等待worker线程处理日志的时间，默认为0，表示无限等待；

• bufferSize：缓冲队列的大小，默认为1024；

• blocking：是否采用阻塞式，默认为true。当队列满时，会同步等待。

<Async name="Async">  <AppenderRef ref="RollingRandomAccessFile"/>  <shutdownTimeout>500</shutdownTimeout>  <bufferSize>1024</bufferSize>  <blocking>true</blocking></Async>

简单解读其设计意图：框架会先提供一个系统缓冲区来缓存即将写入的内容，但是当缓冲区满时，框架还提供了两种策略进行选择，第一种是直接丢弃，第二种是进行等待，但是具体等待多长时间也依然可以配置。

2. Log4j2 AsyncLogger

<dependency>   <groupId>com.lmax</groupId>   <artifactId>disruptor</artifactId></dependency>

与 Log4j 一样，Logback 也有着类似的策略，这里我们就不再赘述它的具体使用方式，下面的表格中，我们总结了在各种策略下的优缺点，希望在大家进行选型时能有所帮助：

使用滚动日志

<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/app.log"                                 filePattern="powered_by/edas-%d{MM-dd-yyyy}-%i.log">    <PatternLayout>        <Pattern>${commonPattern}</Pattern>    </PatternLayout>    <Policies>        <TimeBasedTriggeringPolicy />        <SizeBasedTriggeringPolicy size="100 MB"/>    </Policies>    <DefaultRolloverStrategy>        <max>5</max>    </DefaultRolloverStrategy></RollingRandomAccessFile>

// 不推荐log.debug("Powered by {}", getProductInfoByCode("EDAS"));
// 推荐if (log.isDebugEnabled()) {    log.debug("Powered by {}", getProductInfoByCode("EDAS"));}

上面的逻辑虽然简单，原理也简单易懂，但是我们很多的客户因为这样的代码太多而带来的性能退化案例不在少数，一个很典型的例子就是JSON序列化大的对象，究其原因代码往往是在日常迭代中对于工程实施没有规范，Code Review 流程的缺失而导致恶化。

String product = "EDAS";//推荐log.debug("Powered by {}", product);
//不推荐log.debug("Powered by " + product);

    public StackTraceElement calcLocation(final String fqcnOfLogger) {        if (fqcnOfLogger == null) {            return null;        }        // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace().        final StackTraceElement[] stackTrace = new Throwable().getStackTrace();        boolean found = false;        for (int i = 0; i < stackTrace.length; i++) {            final String className = stackTrace[i].getClassName();            if (fqcnOfLogger.equals(className)) {
                found = true;                continue;            }            if (found && !fqcnOfLogger.equals(className)) {                return stackTrace[i];            }        }        return null;    }

参考链接

Garbage Free: https://logging.apache.org/log4j/2.x/manual/garbagefree.html

Log4j 配置：https://logging.apache.org/log4j/2.x/manual/configuration.html

Logback 配置：https://logback.qos.ch/manual/configuration.html

EDAS 运行时日志动态调整：https://help.aliyun.com/zh/edas/user-guide/dynamic-log-configuration-2261535