我目前正在寻找一种方法,使用log4j2从日志实用程序中获得最佳性能. log4j.properties是
status = error
name = PropertiesConfig
property.log-path = /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles
appender.console.type = Console
appender.console.name = SYSTEM_OUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %m%n
appender.rolling.type = RollingFile
appender.rolling.name = RollingFile
appender.rolling.immediateFlush = true
appender.rolling.fileName = ${log-path}/jsonlogger.json
appender.rolling.filePattern = ${log-path}/%d{yyyyMMdd}_jsonlogger-%i.json
appender.rolling.layout.type = PatternLayout
appender.rolling.layout.pattern = %m%n
appender.rolling.policies.type = Policies
appender.rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.rolling.policies.size.size= 1MB
appender.rolling.strategy.type = DefaultRolloverStrategy
appender.rolling.strategy.max = 4
logger.rolling.name = JSONLogger
logger.rolling.level = debug
logger.rolling.additivity = false
logger.rolling.appenderRef.rolling.ref = RollingFile
rootLogger.level = FATAL
rootLogger.appenderRef.stdout.ref = SYSTEM_OUT
写入100.000个日志条目会占用我的系统大约4623ms.
如果我使用以下设置在我的类路径中创建log4j2.component.properties,以使所有记录器异步.
# Make all loggers asynchronous
Log4jContextSelector = org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
AsyncLogger.RingBufferSize = 262144
AsyncLogger.WaitStrategy = Timeout
AsyncLogger.ThreadNameStrategy = CACHED
AsyncLogger.ExceptionHandler = default handler
然后写入所有100.000个日志条目大约需要7891ms.
根据log4j2 documentation,异步记录器应该能够以同步记录器速率的6-68倍记录消息.
什么配置错了？
==更新1 ==
与此同时,也有一些变化. log4j.properties已被log4j2.xml取代
<?xml version="1.0" encoding="UTF-8"?>
<configuration status="error" name="JSONLogger">
<Properties>
<Property name="log-path">/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles</Property>
</Properties>
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%m%n" />
</Console>
<RollingRandomAccessFile name="RollingFile" fileName="${log-path}/jsonlogger.json"
filePattern="${log-path}/%d{yyyyMMdd}_jsonlogger-%i.json"
immediateFlush="false">
<PatternLayout>
<pattern>%m%n</pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="10 MB" />
</Policies>
<DefaultRolloverStrategy max="4"/>
</RollingRandomAccessFile>
<Async name="Async">
<AppenderRef ref="RollingFile"/>
</Async>
</Appenders>
<Loggers>
<Logger name="JSONLogger" level="trace" additivity="false">
<AppenderRef ref="Async" />
</Logger>
<Root level="fatal">
<AppenderRef ref="Console" />
</Root>
</Loggers>
系统属性Log4jContextSelector已从log4j2.component.properties中删除,现在使用maven shade插件进行设置.
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
<version>2.19.1</version>
<configuration>
<encoding>UTF-8</encoding>
<argLine>-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector</argLine>
</configuration>
</plugin>
无论是否设置了Log4jContextSelector系统属性,运行以下JUnit测试都会提供或多或少相同的性能结果.
@Test
public void orderD_logDebugMessageXMLToJSONFileTest() {
SecureRandom random = new SecureRandom();
String randomString = new BigInteger(130, random).toString();
String xmlString = "<logMessage xmlns=\"http://reddipped.com/jsonlogger\">\n"
+ " <Application>Application Name</Application>\n"
+ " <UserName>User Name</UserName>\n"
+ " <Identifier><FileID>F_" + randomString + "</FileID></Identifier>\n"
+ " <CorrelationID>" + randomString + "</CorrelationID>\n"
+ "</logMessage>";
int messages = 100000;
long start = System.nanoTime();
for (int x = 0; x < messages; x++) {
// Write a debug entry
SoaJSONLogger.getInstance().error(xmlString);
}
Long stop = System.nanoTime();
Long msgsPerSecond = messages / TimeUnit.NANOSECONDS.toSeconds((stop - start));
System.out.println("Messages/s : " + msgsPerSecond) ;
System.out.println("Duration : " + (stop - start) ) ;
Assume.assumeTrue("Slow performance " + msgsPerSecond + " < 10000 ", msgsPerSecond >= 10000);
}
所有结果都在附近
消息/ s：10000
持续时间：10630754228
==更新2 ==
如果我从类路径和Log4jContextSelector系统属性中删除disruptor jar,性能仍然是10000条消息/秒.
恢复jar和系统属性并将log4j2.xml中元素Configuration的属性状态设置为TRACE时,记录器输出显示为SYSTEM
2017-01-23 21:45:14,392 main DEBUG LoggerContext[name=AsyncContext@232204a1, org.apache.logging.log4j.core.async.AsyncLoggerContext@58695725] started OK.
2017-01-23 21:45:14,393 main DEBUG AsyncLogger.ThreadNameStrategy=CACHED
2017-01-23 21:45:18,961 AsyncAppender-Async TRACE DefaultRolloverStrategy.purge() took 2.0 milliseconds
2017-01-23 21:45:18,966 AsyncAppender-Async DEBUG RollingFileManager executing synchronous FileRenameAction[/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-1.json, renameEmptyFiles=false]
2017-01-23 21:45:18,972 AsyncAppender-Async TRACE Renamed file /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-1.json with Files.move
2017-01-23 21:45:21,987 AsyncAppender-Async TRACE DefaultRolloverStrategy.purge() took 0.0 milliseconds
2017-01-23 21:45:21,991 AsyncAppender-Async DEBUG RollingFileManager executing synchronous FileRenameAction[/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-2.json, renameEmptyFiles=false]
2017-01-23 21:45:21,991 AsyncAppender-Async TRACE Renamed file /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-2.json with Files.move
基于此我只能得出结论,记录器是异步的.只有性能是一样的.
==更新3 ==
用RandomAccessFile替换RollingRandomAccessFile.
<Properties>
<Property name="log-path">/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles</Property>
</Properties>
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%m%n" />
</Console>
<RandomAccessFile name="RollingFile" fileName="${log-path}/jsonlogger.json">
<PatternLayout>
<pattern>%m%n</pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="10 MB" />
</Policies>
<DefaultRolloverStrategy max="4"/>
</RandomAccessFile>
<Async name="Async">
<AppenderRef ref="RollingFile"/>
</Async>
</Appenders>
<Loggers>
<Logger name="JSONLogger" level="trace" additivity="false">
<AppenderRef ref="Async" />
<!--<AppenderRef ref="Console" />-->
</Logger>
<Root level="fatal">
<AppenderRef ref="Console" />
</Root>
</Loggers>
在外部循环中创建SoaJSONLogger的实例并添加一些“预热”日志事件.
int messages = 100000;
SoaJSONLogger l = SoaJSONLogger.getInstance() ;
l.error(xmlString);l.error(xmlString);l.error(xmlString);l.error(xmlString);l.error(xmlString);
long start = System.nanoTime();
for (int x = 0; x < messages; x++) {
// Write a debug entry
l.error(xmlString);
}
Long stop = System.nanoTime();
性能没有变化;
消息/ s：10000
持续时间：10996023059
==更新4 ==
由remco建议添加测试代码
// plain logger
org.apache.logging.log4j.Logger log4j2Logger = org.apache.logging.log4j.LogManager.getLogger("JSONLogger") ;
log4j2Logger.error(xmlString);
long startl = System.nanoTime();
for (int x = 0; x < messages; x++) {
// Write a debug entry
log4j2Logger.error(xmlString);
}
Long stopl = System.nanoTime();
System.out.println("startl : " + startl) ;
System.out.println("stopl : " + stopl) ;
Long msgsPerSecondl = (long) 0 ;
if (TimeUnit.NANOSECONDS.toSeconds(stopl - startl) == 0) {
msgsPerSecondl = (long) messages ;
} else {
msgsPerSecondl = messages / TimeUnit.NANOSECONDS.toSeconds((stopl - startl));
}
System.out.println("Messages/s : " + msgsPerSecondl) ;
System.out.println("Duration : " + (stopl - startl) ) ;
// plain logger end
性能现在是100000条消息/秒(之前的10倍性能)
解决方法:
SoaJSONLogger :: error中似乎存在一些逻辑,导致性能比使用标准org.apache.logging.log4j.Logger进行日志记录时差10倍.也许这是一个调查的好地方.
您可以尝试的另一件事是使用AsyncLogger进行配置：
<AsyncLogger name="JSONLogger" level="trace" additivity="false">
<AppenderRef ref="RollingFile" />
</AsyncLogger>