Log4j是一个由Java编写可靠、灵活的日志框架,是Apache旗下的一个开源项目;现如今,Log4j已经被移植到了C、C++、Python等语言中,服务更多的Developer;
使用Log4j,我们更加方便的记录了日志信息,它不但能控制日志输出的目的地,也能控制日志输出的内容格式;通过定义不同的日志级别,可以更加精确的控制日志的生成过程,从而达到我们应用的需求;这一切,都得益于一个灵活的配置文件,并不需要我们更改代码。
在Log4j中,主要由三个重要组件构成:
首先,需要在应用的pom.xml中添加依赖:
<dependency>
<groupId>log4j</groupId>
<artifactId>log4j</artifactId>
<version>1.2.17</version>
</dependency>
其次,声明测试代码:
public class log4jDemo {
Logger log= Logger.getLogger(log4jDemo.class);
@Test
public void test(){
log.trace("Trace Message!");
log.debug("Debug Message!");
log.info("Info Message!");
log.warn("Warn Message!");
log.error("Error nihao 你好!");
log.fatal("Fatal Message!");
}
}
最后,在classpath下声明配置文件:log4j.properties 或者 log4j.xml;
例1:log4j.properties:
log4j.rootLogger = INFO, FILE, CONSOLE
log4j.appender.FILE=org.apache.log4j.FileAppender
log4j.appender.FILE.File=e:/log.out
log4j.appender.FILE.ImmediateFlush=true
log4j.appender.FILE.Threshold = DEBUG
log4j.appender.FILE.Append=true
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.conversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.Target=System.out
log4j.appender.CONSOLE.ImmediateFlush=true
log4j.appender.CONSOLE.Threshold = DEBUG
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.encoding=UTF-8
log4j.appender.CONSOLE.layout.conversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
例2:log4j.xml:
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration>
<appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<param name="target" value="System.out"/>
<param name="immediateFlush" value="true"/>
<param name="threshold" value="DEBUG"/>
<param name="append" value="true"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d - %c -%-4r [%t] %-5p %x - %m%n" />
</layout>
</appender>
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="true"/>
<param name="Threshold" value="DEBUG"/>
<param name="Append" value="true"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
<category name="com.jiaboyan" additivity="false">
<level value="error"></level>
<appender-ref ref="CONSOLE" />
</category>
<root>
<priority value="info" />
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</root>
</log4j:configuration>
通过以上步骤,log4j就可以正常的运行了。
接下来,具体讲解下log4j配置文件中的各个属性:(以log4j.properties为例讲解);
在我们的应用中,日志操作几乎是每个方法中必备的行为,不管是记录请求的信息,还是辅助问题的定位,日志信息都起着重要的作用,极大的方便了程序开发。
但与之俱来的是,由于频繁的IO和磁盘的读写,应用的性能也随之降低。并且,java的IO是阻塞式,加锁后导致也同样降低性能。因此对于日志的调优,就成了必备功课。
首先,抛开频繁的IO和磁盘读写不谈,就单纯讨论log4j的性能而言,在高并发的情况下,log4j的锁也会导致应用的性能下降,究其原因,还是看以下的代码:
Category类的callAppenders方法:
//日志对象唤起日志输出目的地Appender:进行日志打印
public void callAppenders(LoggingEvent event) {
int writes = 0;
//遍历日志对象集合
for(Category c = this; c != null; c=c.parent) {
//Category是Logger的父类,此处的c就是请求的日志对象本身:
synchronized(c) {
//此处加锁了:
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
}
通过以上代码,我们可以发现,为了获得对应日志对象的Appender,会在每次获取之前都加上synchronized同步锁。无论多少个线程进行请求,到此处都需要进行获取锁的操作,才可以进行日志的打印。这也就是说,线程越多,并发越大,此处的锁的竞争越激烈,进而导致系统性能的降低。
其次,我们再回过头来看下IO和磁盘读写的问题。在实际的生产环境下,系统所产生的日志信息需要保存在磁盘文件中,以便日后进行系统分析,或者系统问题的查找。
之前,我们说过Java的IO是阻塞式的,下面就来看下实际的代码:
JDK1.7中的sun.nio.cs.StreamEncoder类:
public void write(char cbuf[], int off, int len) throws IOException {
synchronized (lock) {
ensureOpen();
if ((off < 0) || (off > cbuf.length) || (len < 0) ||
((off + len) > cbuf.length) || ((off + len) < 0)) {
throw new IndexOutOfBoundsException();
} else if (len == 0) {
return;
}
implWrite(cbuf, off, len);
}
}
可以看到,在java-IO流最终输出阶段,也同样加了synchronized同步锁。这也就是我们所说的java阻塞式IO。
在2.3节中,笔者提到了FileAppender,该类主要功能就是将日志信输出到磁盘文件中。其中,有ImmediateFlush、BufferedIO、BufferSize这三个属性尤为值得关注;
当ImmediateFlush=true时候,表示每一条打印日志请求都会被立即输出,也就是立刻同步到磁盘中去。在高并发下,系统性能受到很大的影响,IO和磁盘读写数大大提升。
当ImmediateFlush=false时候,与上面正好相反,表示每一条打印日志请求不会被立即输出,会使用java.io.OutputStreamWriter的缓存,缓存大小为1024字节。
当ImmediateFlush=false、BufferedIO=true、BufferSize=8192时候,表示使用java.io.BufferedWriter缓存,缓存大小为默认8192字节,每一条打印请求不会立即输出,当缓存达到8192字节后才会落盘操作。这样一来,大大减少了IO和磁盘读写操作,提升了系统的性能。
测试代码:
public class log4jDemo {
Logger log = Logger.getLogger(log4jDemo.class);
@Test
public void test() throws InterruptedException {
for(int x=0;x<20;x++) {
long start = System.currentTimeMillis();
for (int y = 0; y < 50; y++) {
log.info("Info Message!");
}
long time = System.currentTimeMillis() - start;
System.out.println(time);
}
}
}
例子1:当ImmediateFlush=true时
配置文件:
<log4j:configuration>
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="false"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
<root>
<priority value="info" />
<appender-ref ref="FILE" />
</root>
</log4j:configuration>
例子1测试结果:(单位毫秒)
931 631 372 371 374 371 371 383 376 439 376 383 372 416 393 368 368 366 376 376 394 384 373 396 371 380 368 382 373 369 373 379 374 370 381 367 371 379 372 385 381 379 375 398 409 415 392 371 403 406
例子2:当ImmediateFlush=false时
配置文件:
<log4j:configuration>
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="true"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
<root>
<priority value="info" />
<appender-ref ref="FILE" />
</root>
</log4j:configuration>
例子2测试结果:(单位毫秒)
845 693 344 338 353 340 372 373 345 337 332 341 345 352 346 332 336 333 379 359 333 330 356 338 333 341 346 331 341 337 339 329 341 339 339 334 341 328 331 329 328 330 329 336 334 332 332 331 333 330
例子3:当ImmediateFlush=false、BufferedIO=true、BufferSize=8192时
配置文件:
<log4j:configuration>
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="false"/>
<param name="bufferedIO" value="true"/>
<param name="bufferSize" value="8192"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
<root>
<priority value="info" />
<appender-ref ref="FILE" />
</root>
</log4j:configuration>
例子3测试结果:(单位毫秒)
731 853 356 332 336 334 334 334 334 331 332 344 331 330 332 332 330 331 340 334 329 333 331 335 334 334 332 331 336 335 331 354 334 333 334 354 331 333 334 332 333 331 347 332 333 330 332 330 333 331
例子4:使用AsyncAppender异步处理
配置文件:
<log4j:configuration>
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="bufferedIO" value="true"/>
<param name="bufferSize" value="8192"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
<appender name="AsyncAppender" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="FILE"/>
</appender>
<root>
<priority value="info" />
<appender-ref ref="AsyncAppender" />
</root>
</log4j:configuration>
例子4测试结果:(单位毫秒)
292 178 146 177 216 278 215 147 136 102 92 96 97 93 93 95 93 94 92 93 97 93 94 93 95 94 96 107 94 91 93 94 99 98 96 95 95 98 102 95 93 92 91 107 155 137 110 98 93 93
通过以上4个例子,我们可以看出,性能最差的是ImmediateFlush=true的时候,而性能最好的就是开启日志异步AsyncAppender处理的时候;
上一小节,我们提到了log4j的缓存,通过测试结果来看,在开启缓存的情况下,log4j的性能得到了大幅度提升。既然缓存的优势这么明显,为什么log4j不默认开启缓存呢?
缓存的存在,有利有弊。利,提升系统响应性能;弊,当系统因为异常而崩溃,又或者jvm被强行关闭,从而导致缓存中的数据丢失,日志不存在,无法及时确定异常原因。我想,这个才是log4j并没有默认开启缓存的原因!
日志的存在,一方面为了记录系统请求的信息;另一方面,帮助develpoer及时发现、排除错误原因。如果连日志的完整性都不能保留,那么日志存在的意义又是什么?所以,log4j并没有将缓存设置为默认开启,只是提供了一个选项;
那么,我们如何使鱼和熊掌可以兼得呢?在log4j提供的api中暂时无法实现此需求,不过jvm向我们提供了一个方法,可以帮助我们实现,这就是jvm关闭钩子程序;
在jvm中注册一个钩子程序,当jvm关闭的时候,会执行系统中已经设置的所有通过方法addShutdownHook添加的钩子,当系统执行完这些钩子后,jvm才会关闭。
那么,在我们的日志中,如何实现钩子程序呢?请看下面的实现:
测试代码:
public class log4jDemo {
Logger log = Logger.getLogger(log4jDemo.class);
@Test
public void test() throws InterruptedException {
log.info("Info Message!");
}
}
配置文件:(没有开启缓存,立即刷入磁盘)
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="true"/> 关闭缓存
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
结果:(程序运行结束后,生成日志文件信息)
立刻刷入,日志信息落盘;
接下来,修改配置文件信息,开启缓存,不立刻刷入磁盘;
<appender name="FILE" class="org.apache.log4j.FileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="false"/> 开启缓存
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
结果:(程序运行结束后,生成日志文件信息)
jvm运行结束,日志信息没有保存到磁盘中来,日志丢失;
最后,我们添加钩子程序,看看结果如何?
创建新的Appender,继承FileAppender,在构造中添加钩子程序代码:
public class HookFileAppender extends FileAppender {
public HookFileAppender(){
super();
//添加钩子程序:
Runtime.getRuntime().addShutdownHook(new Log4jHockThread());
}
public HookFileAppender(Layout layout, String filename) throws IOException {
super(layout,filename);
//添加钩子程序:
Runtime.getRuntime().addShutdownHook(new Log4jHockThread());
}
public HookFileAppender(Layout layout, String filename, boolean append) throws IOException {
super(layout,filename,append);
//添加钩子程序:
Runtime.getRuntime().addShutdownHook(new Log4jHockThread());
}
public HookFileAppender(Layout layout, String filename, boolean append, boolean bufferedIO,
int bufferSize) throws IOException {
super(layout,filename,append,bufferedIO,bufferSize);
Runtime.getRuntime().addShutdownHook(new Log4jHockThread());
}
class Log4jHockThread extends Thread{
@Override
public void run() {
//jvm结束之前,运行flush操作,将日志落盘;
if(qw != null){
qw.flush();
}
}
}
}
配置文件修改:(新的appender,开启缓存)
<appender name="HOOKFILE" class="com.jiaboyan.logDemo.HookFileAppender">
<param name="File" value="e:/log.out" />
<param name="ImmediateFlush" value="false"/>
<!--<param name="bufferedIO" value="true"/>-->
<!--<param name="bufferSize" value="8192"/>-->
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %5p %c{1}:%L - %m%n" />
</layout>
</appender>
<root>
<priority value="info" />
<appender-ref ref="HOOKFILE" />
</root>
结果为:
在jvm结束之前,开启了Log4jHockThread线程,将缓存中的日志进行落盘操作,避免了日志的丢失。