Log4j2 最佳实践

szh765

已于 2023-07-06 12:35:37 修改

阅读量1k

点赞数 2

分类专栏： Java性能文章标签： log4j java spring

于 2023-07-01 19:50:52 首次发布

本文链接：https://blog.csdn.net/shizihao1996/article/details/131459053

版权

Java性能专栏收录该内容

1 篇文章 0 订阅

订阅专栏

1. 配置建议

建议使用 log4j2 v2.17.1，

2.17.0 已知有远程执行代码缺陷 CVE-2021-44832, Apache log4j2 远程代码执行漏洞风险公告（CVE-2021-44832）
建议使用异步模式, 具体内容详见2. Log4j2异步模式。
建议设置 includeLocation=“false” ，同时 PatternLayout 不要使用 %L、%C、%method 等含有“位置信息”的配置项，可以使用%c或%logger代替。
exclude 不必要的 jar 包，避免 jar 包冲突引发问题，详请参见 log4j jar 包冲突问题分析和解决。
建议不要将大量日志使用 ConsoleAppender 打印，即使 upjas 可以将控制台内容重定向到 server.log。
建议使用 RollingRandomAccessFile 做为 appender。
日志格式符合规范： logTime|thread|logLvl|requestId|LogID # msg ，对应 pattern 配置： %d{yyyy-MM-dd HH:mm:ss SSS}|%t|%-5p|%X{requestId}|%X{LogID} #%m%n ，如需在日志头部附加其他字段，应在规范格式后自定义添加。
对于日志输出频繁且大量的应用，应配置基于大小和时间的双重文件滚动策略。
ERROR 等报错日志额外记录一份日志文件, 同时允许 INFO 日志文件中存在 ERROR 日志，以便于排查问题。
日志体 msg 中关键信息按照指定关键字打印，多个关键字以 | 分隔。
若应用使用 cron 表达式（CronTriggeringPolicy）滚动策略做日志切割，同时应注意配置。DefaultRolloverStrategy 标签，指定当前滚动单元最多保留的日志文件个数，避免由于日志保留个数较少而造成日志丢失。若不配置，默认当前滚动单元最多保留 7 个滚动日志。
建议日志滚动、压缩等耗费性能的操作，配置在非整点进行。
建议在子 AsyncLogger / 子 Logger 中将 additivity 属性配置为 false ，避免日志重复打印。
建议在 Configuration 标签中添加 monitorInterval 属性，以支持配置动态刷新。
日志空间需求=日志滚动阈值 + 日志留存个数日志滚动阈值1/压缩比(对于 gz 压缩比一般会是几十，具体根据应用日志压缩后计算). 比如日志空间需求=500M+205001/50=700M。
当日志产生速度大于 appender 记录速度时，队列会被填满，应用线程将会阻塞。可以设置。log4j2.AsyncQueueFullPolicy=Discard，在队列满时丢弃。
建议使用RandomAccessFileAppender, 并且设置 immediateFlush=“false” 。相对于FileAppender, RandomAccessFileAppender使用Bytebuffer+RandomAccessFile而不是BufferedOutputStream。如果设置immediateFlush=“true”，每一次log事件写入缓存将会立即被flush到磁盘上，当设置immediateFlush="false"时，log日志会被批量的flush到磁盘。

注意，当设置immediateFlush="false"时，tail -f将不能实时观察最新日志，

2. Log4j2 异步模式

Log4j2 的 AsyncLogger 使用的是 Disruptor 框架作为线程间消息传递的工具，而 Logback, Log4j 1.2 和 Log4j2 的 AsyncAppender 使用的是 ArrayBlockingQueue。 Disruptor 框架的吞吐量和延迟明显好于 ArrayBlockingQueue。

参考 Asynchronous Logging - Peak Throughput Comparison 和 Throughput Performance Testing

2.1 Disruptor vs ArrayBlockingQueue

多线程访问队列时，ArrayBlockingQueue 采用的 ReentrantLock 重量级锁，而 Disruptor 采用 CAS 的方式。
Disruptor 队列中的关键属性之间会被填充冗余字段，比如队列头和队列尾，从而使得不同的属性位于不同的 cpu 缓存行上，当生产者和消费者分别并发的对其进行修改时，可以避免缓存失效。
Disruptor 使用环形队列(RingBuffer)，和 ArrayBlockingQueue 不同，RingBuffer 不需要频繁地分配和释放，可以避免分配带来的消耗，避免垃圾回收，同时可以更好地利用 CPU 的缓存机制更加友好。

参考 Disruptor 详解

2.2 开启方式

因为 AsyncLogger 依赖 Disruptor 框架，所以下面每种方式使用前都需要添加 Disruptor 依赖。Disruptor 应采用 3.4.4 及以上版本，以免在高并发使得 disruptor 队列满时触发同步日志，导致应用线程阻塞

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

2.2.1 全局异步开启方式

方式一

在 JVM 启动参数后添加 -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 或者 -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.BasicAsyncLoggerContextSelector

方式二

编辑 log4j2.component.properties 文件

添加Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
或 Log4jContextSelector=org.apache.logging.log4j.core.async.BasicAsyncLoggerContextSelector

2.2.2 混合异步开启方式

将原 Log4j2 配置文件中的 <Logger> 标签替换成 <AsyncLogger>， <Root> 标签替换成 <AsyncRoot>

不建议在采用2.2.1 全局异步开启方式的同时使用 2.2.2 混合异步开启方式 （见官方文档 Making All Loggers Asynchronous）

不建议使用 AsyncAppender, 即使在 Log4j 之前的版本中，AsyncAppender 与 AsyncLogger 混合使用的 Bug 已经被修复(见 Difference between AsyncLogger and AsyncAppender in Log4j2)

经实际压力测试，方式2.2.1与2.2.2性能上差别不大(前提是2.2.2中的所有Logger均为AsyncLogger)

3. location信息对性能的影响

在 LayoutPattern 中，%C 和 %class, %F 和 %file，%l 和 %location，%L 和 %line，%M 和 %method 都会采用采用 new Throwable().getStackTrace()的方式获取了当前日志操作所在的堆栈列表，日志操作方法(比如 log.info())的下一个栈帧就是当前 log 所处的方法，这是一种非常耗时的操作

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-WmtuEmPy-1688617725060)(http://172.21.125.3:19403/api/v2/blog/getImageFdfs?fileId=group2/M00/06/C1/CskR6GSjxIOATt4nAAFypqFRh0Q810.png)]

火焰图对比

以下是不包含 location 信息的部分火焰图，其中 LogMessageTrackRecursion()方法占用的程序执行抽样次数百分比为 8.19%

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-ikhmMgy5-1688617725063)(http://172.21.125.3:19403/api/v2/blog/getImageFdfs?fileId=group2/M00/04/24/rBV9D2Sjw-eAfhanAAUheFkqgpM275.png)]

这是包含 location 信息的部分火焰图, 其中，其中 LogMessageTrackRecursion()方法占用的程序执行抽样次数百分比为 62.89%，getLocation()为 58.89%

在这里插入图片描述

替换方法

在 LayoutPattern 中使用 %C 或 %logger，这种方式可以记录 logger 的 name，在日常开发中，logger 的 name 一般都是当前 logger 所在函数的 class 全限定名。比如 Logger log = LoggerFactory.getLogger(Example.class);, lombok 的 @Slf4j, @Log4j, @Log4j2 注解也同样遵循这种方式。

压测结果

测试项目总体配置

有三个接口/full_async, /mix_async和 /sync, 每个接口接受一个request body带有data的post请求, 然后/full_async接口会将data异步打印到一个文件上两次， /mix_async会分别将data同步打印到一个文件，并且会异步打印到另一个文件， /sync接口则会用同步打印到一个文件两次

压测请求为

curl -X POST -H "Content-Type: application/json" -d@req.json http://[ip]:[port]/mix_async

{"data":"94F50FA414DE928BF546026A5F570D62666E3C9264DF6EC5A9D8D5B3BCE0E150355C7F70C6964FC39C7B65972A64767460D69FE4962AABD1112DAA387C30D82C99FC266A8D68E13657C8066AE24B64CF0A2FCC451438BCAD889EDC6054661A0780E72395FC29E4FCDEB6AA529605F1D7"}

其他测试配置
1. appender采用 RollingRandomAccessFile，并且配置immediateFlush=“false”
2. 没有配置Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

项目代码

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

@RestController
class TestController {
	@PostMapping("/full_async")
	public String fullAsync(@RequestBody String data) {
		AsyncFunc.asyncLog(data);
		AsyncFunc.asyncLog(data);
		return data;
	}

	@PostMapping("/mix_async")
	public String mixAsync(@RequestBody String data) {
		AsyncFunc.asyncLog(data);
		SyncFunc.syncLog(data);
		return data;
	}

	@PostMapping("/sync")
	public String sync(@RequestBody String data) {
		SyncFunc.syncLog(data);
		SyncFunc.syncLog(data);
		return data;
	}
}
@Slf4j
class AsyncFunc {
	public static void asyncLog(String data) {
		log.info(data);
	}
}

@Log4j2
class SyncFunc {
	public static void syncLog(String data) {
		log.info(data);
	}
}

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <Appenders>
        <Console name="Console">
            <PatternLayout pattern="[%-5p] %logger %d  - %m%n"  />
        </Console>
        <RollingRandomAccessFile name="AsyncFileAppender"
                                 fileName="async.log"
                                 filePattern="async.log.%i.gz">
            immediateFlush="false" append="false">
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <PatternLayout pattern="[%-5p]  %logger %d  - %m%n"  />
            <!-- max=20表示最多保留20个日志文件 -->
            <DefaultRolloverStrategy max="20"/>
            <!-- 当前appender只打印info日志，warn及以上日志忽略，由后面的appender决定是否需要打印 -->
        </RollingRandomAccessFile>

        <RollingRandomAccessFile name="SyncFileAppender"
                                 fileName="sync.log"
                                 filePattern="sync.log.%i.gz">
            immediateFlush="false" append="false">
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
            </Policies>
            <PatternLayout pattern="[%-5p] %logger %d  - %m%n"  />
            <!-- max=20表示最多保留20个日志文件 -->
            <DefaultRolloverStrategy max="20"/>
            <!-- 当前appender只打印info日志，warn及以上日志忽略，由后面的appender决定是否需要打印 -->
        </RollingRandomAccessFile>

    </Appenders>

    <Loggers>

        <Root level="info" includeLocation="false" >
            <AppenderRef ref="Console"/>
        </Root>

        <AsyncLogger level="info" name="com.example.demo.AsyncFunc" includeLocation="false" additivity="false">
            <AppenderRef ref="AsyncFileAppender"/>
        </AsyncLogger>

        <Logger level="info" name="com.example.demo.SyncFunc" includeLocation="false" additivity="false" >
            <AppenderRef ref="SyncFileAppender"/>
        </Logger>
    </Loggers>
</configuration>

结果展示

测试主机配置 4c8g

极限并发测试结果

Logger 标签属性 includeLocation=“false”, PatternLayout为 [%-5p] %d - %m%n

并发数	是否包含位置信息	异步/同步	sleep time	CPU	QPS	RT
200	否	异步	/	82.28%	23914	7
200	否	半异步	/	71.55%	18354	9
200	否	同步	/	68.94%	17012	10

Logger 标签属性 includeLocation=“true”、PatternLayout 为 [%-5p] %C %L %d - %m%n

并发数	是否包含位置信息	异步/同步	sleep time	CPU	QPS	RT
200	是	异步	/	94.65%	12814	15
200	是	半异步	/	82.69%	9341	19
200	是	同步	/	74.63%	7594	23

Logger 标签属性 includeLocation=“true”、PatternLayout 为 [%-5p] %logger %d - %m%n

并发数	是否包含位置信息	异步/同步	sleep time	CPU	QPS	RT
200	否, 采用 %logger	异步	/	80.30%	23342	8
200	否, 采用 %logger	半异步	/	73.41%	18114	9
200	否, 采用 %logger	同步	/	71.05%	16767	10

非高并发场景下测试结果

在该场景中，每次spring应用每次接收http请求将会睡眠20ms，使用jmeter压测结果如下：

并发数	是否包含位置信息	异步/同步	sleep time	CPU	QPS	RT
50	否	异步	20ms	11.26%	2375	21
50	否	半异步	20ms	8.62%	2368	21
50	否	同步	20ms	16.62%	2366	21
50	是	异步	20ms	22.57%	2242	22
50	是	半异步	20ms	28.7%	2209	21
50	是	同步	20ms	26.88%	2287	21
200	否	异步	20ms	52.83%	9399	21
200	否	半异步	20ms	49.49%	9408	20
200	否	同步	20ms	51.78%	9350	20
200	是	异步	20ms	63.12%	6659	30
200	是	半异步	20ms	63.57%	6173	30
200	是	同步	20ms	67.27%	6929	27

结论

对于不吃cpu资源，并且并发不高的系统，可以采用附带location信息的方式。但是对于高并发系统，推荐使用AsyncLogger+includeLocation="false"模式，对于吃cpu资源的系统，也推荐使用includeLocation=“false”。

4. 示例

4.1 示例一

该示例采用设置 contextSelector 的方式，开启全局异步。

1. 配置 pom 依赖

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


<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.17.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-1.2-api</artifactId>
    <version>2.17.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.17.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.17.1</version>
</dependency>
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.4.4</version>
</dependency>

2. 配置 log4j2.component.properties

Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector #开启全局异步
log4j2.AsyncQueueFullPolicy=Discard #队列满后丢弃日志
log4j2.DiscardThreshold=INFO #丢弃级别INFO及以下

3.配置 log4j2-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<!-- 每隔30秒，log4j2会刷新一次配置。 -->
<Configuration status="INFO" monitorInterval="30">

    <Properties>
        <!-- 应用需要修改为合适的log路径 -->
        <Property name="baseLogDir">logs</Property>
        <Property name="pattern">%d{yyyy-MM-ddHH:mm:ssSSS}|%t|%-5p|%X{requestId}|%X{LogID} # %m%n</Property>
        <Property name="packagePath">com.example.demo</Property>
    </Properties>

    <Appenders>
        <!-- 系统日志，可以作为root logger的appender，供打印一些中间件的日志 -->
        <RollingRandomAccessFile name="SYS_APPENDER" immediateFlush="false" fileName="${baseLogDir}/server.log" filePattern="${baseLogDir}/server.log.%d{yyyyMMddHH}.%i.gz">
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
                <!-- 设置在每小时的第45分钟滚动日志-->
                <CronTriggeringPolicy schedule="0 45 * * * ?" />
            </Policies>
            <Filters>
                <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY" />
            </Filters>
            <!-- max=20标识一小时内最多产生6个日志文件；若不配置，默认保留7个滚动日志文件 -->
            <DefaultRolloverStrategy max="6">
                <!-- 对于指定的路径下的指定后缀的文件，只保留1天的日志文件，则磁盘上最多会有24小时*6个日志文件 -->
                <Delete basePath="${baseLogDir}" maxDepth="1">
                    <IfFileName glob="*.gz" />
                    <IfLastModified age="1d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingRandomAccessFile>
        <!-- 应用info日志 -->
        <RollingRandomAccessFile name="APP_APPENDER" immediateFlush="false" fileName="${baseLogDir}/app.log" filePattern="${baseLogDir}/app.log.%d{yyyyMMddHH}.%i.gz">
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
                <CronTriggeringPolicy schedule="0 45 * * * ?" />
            </Policies>
            <Filters>
                <!-- 打印INFO级别以上的日志 -->
                <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY" />
            </Filters>
                        <DefaultRolloverStrategy max="20">
                <!-- 磁盘上最多会有3天*24小时*20个日志文件 -->
                <Delete basePath="${baseLogDir}" maxDepth="1">
                    <IfFileName glob="*.gz" />
                    <IfLastModified age="3d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingRandomAccessFile>
        <!-- 应用错误日志 -->
        <RollingRandomAccessFile name="APPERROR_APPENDER" immediateFlush="false" fileName="${baseLogDir}/apperror.log"
                                 filePattern="${baseLogDir}/apperror.log.%d{yyyyMMddHH}.%i.gz">
            <PatternLayout>
                <Pattern>${pattern}</Pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB" />
                <CronTriggeringPolicy schedule="0 45 * * * ?" />
            </Policies>
            <Filters>
                <ThresholdFilter level="WARN" onMatch="ACCEPT" onMismatch="DENY" />
            </Filters>

            <DefaultRolloverStrategy max="10">
                <!-- 磁盘上最多会有3*24小时*10个日志文件 -->
                <Delete basePath="${baseLogDir}" maxDepth="1">
                    <IfFileName glob="*.gz" />
                    <IfLastModified age="3d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingRandomAccessFile>
    </Appenders>
    <Loggers>
        <!-- 应用包之外的日志写入server.log, 如第三方jar包，中间件等，级别在warn之上 -->
        <Root level="WARN" includeLocation="false">
            <AppenderRef ref="SYS_APPENDER" />
        </Root>
        <!-- additivity建议设置为false以避免在root logger中重复打印 -->
        <!-- includeLocation建议设置为false，关闭位置打印 -->
        <Logger name="${packagePath}" level="INFO" includeLocation="false" additivity="false">
            <AppenderRef ref="APP_APPENDER" />
            <AppenderRef ref="APPERROR_APPENDER" />
        </Logger>
    </Loggers>
</Configuration>