最近一段时间,在跟进一个项目的性能优化时,发现当系统qps达到一定程度时,会有大量线程阻塞在写日志的阶段,打印线程栈,阻塞信息如下:
"pool-60-thread-7" #820 prio=5 os_prio=0 tid=0x00007f67fc007000 nid=0x3b4 waiting for monitor entry [0x00007f6747bf9000]
java.lang.Thread.State:BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00000000f9768ef0> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.log(Category.java:856)
at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:177)
at org.apache.http.impl.conn.Wire.wire(Wire.java:77)
at org.apache.http.impl.conn.Wire.input(Wire.java:115)
经过查阅,发现这是log4j同步写入导致的,结合jvisualvm,发现日志的写入占用CPU时间也不少。究其原因,主要是log4j在同步写入时,会做同步,发生问题的代码片段如下,即:
public void callAppenders(LoggingEvent event) {
int writes = 0;
for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender, removeAppender,...
synchronized(c) {
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
}
我们的log配置采用的properties文件的方式进行的,这种方式经过加载后,默认的就是同步方式,加载过程如:
File logConfig = new File("log4j.properties");
if (logConfig.exists()) {
PropertyConfigurator.configure(logConfig.toString());
}
如要采用异步方式,需要采用xml的方式配置,并用DOMConfigurator加载配置。
异步和同步的主要区别在于,异步会设置一个缓冲区,当缓冲区写满会,才会刷新到文件,没有同步竞争的环节,效率更高。
接下来,贴一个log4j.xml的配置,备忘。
<?xml version="1.0" encoding="UTF-8"?>
<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/' >
<appender name="console" class="org.apache.log4j.DailyRollingFileAppender">
<param name="Target" value="System.out"/>
<param name="Threshold" value="ERROR"/>
<param name="Append" value="true"/>
<param name="encoding" value="UTF-8"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %5p %c:%L - %m%n"/>
</layout>
</appender>
<appender name="debugLog" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="../logs/debug.log" />
<param name="Append" value="true" />
<param name="BufferSize" value="8192" />
<param name="ImmediateFlush" value="false" />
<param name="BufferedIO" value="true" />
<param name="Threshold" value="INFO" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %5p %c:%L - %m%n" />
</layout>
<param name="encoding" value="UTF-8" />
</appender>
<appender name="errorLog" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="../logs/error.log" />
<param name="Append" value="true" />
<param name="Threshold" value="ERROR" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %5p %c:%L - %m%n" />
</layout>
<param name="encoding" value="UTF-8" />
</appender>
<appender name="async" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="debugLog"/>
</appender>
<category name="asyncLog" additivity="false">
<priority value="info" />
<appender-ref ref="async" />
</category >
<!-- 根logger的设置-->
<root>
<priority value ="info"/>
<appender-ref ref="async"/>
</root>
</log4j:configuration>
注意其中缓冲区的设置,异步appender的设置,以及root日志的设置。
最后,加载日志的代码:
File logConfig = new File("log4j.xml");
if (logConfig.exists()) {
Document doc = null;
try {
System.out.println("User config " + logConfig);
doc = DocumentBuilderFactory.newInstance().newDocumentBuilder().parse(logConfig);
DOMConfigurator.configure(doc.getDocumentElement());
} catch (Exception e) {
System.out.println("read log.xml error ,exit -1");
e.printStackTrace();
System.exit(-1);
}
}