大家在编程时经常不可避免地要使用到一些日志操作,比如开发阶段的调试信息、运行时的日志记录及审计。调查显示,日志代码占代码总量的4%。通常大家可以简单地使用System.out.println()语句输出日志信息,但是往往会有一些判断,比如:
if (someCondition) {
System.out.println("some information.");
}
这些判断造成正常的程序逻辑中混杂了大量的输出语句。而在开发阶段写下的这些判断仅为了调试的语句,在开发完成时需要查找并移除。部署运行后,尤其是在一些企业应用系统中,还经常需要进一步调试,这时就遇到了更大的麻烦。所以,我们需要一套完备的、灵活的、可配置的日志工具。Log4J就是优秀的选择。
Log4J是Apache软件基金会Jakarta项目下的一个子项目,是用Java编写的优秀日志工具包。通过Log4J可以在不修改代码的情况下,方便、灵活地控制任意粒度的日志信息的开启或关闭,然后使用定制的格式,把日志信息输出到一个或多个需要的地方。并且,Log4J还有一条平滑的学习曲线,在三分钟内就可学会它的简单使用。随着使用深入,你会发现Log4J功能的强大,几乎可以满足日志方面的所有需要。
快速入门
先看一段代码,看看Log4J是多么易于上手,代码如下:
package org.javaresearch.log4j;
import org.apache.log4j.*;
public class TestLog4J {
static Logger log = Logger.getLogger(TestLog4J.class.getName());
public static void main(String args[]) {
BasicConfigurator.configure();
// logging的各种方法
log.debug("Start of main()");
log.info("Just testing a log message with priority set to INFO");
log.warn("Just testing a log message with priority set to WARN");
log.error("Just testing a log message with priority set to ERROR");
log.fatal("Just testing a log message with priority set to FATAL");
// 另一种不方便的格式
log.log(Priority.DEBUG, "Testing a log message use a alternate form");
log.debug("End of main().");
}
}
把这段代码保存在一个目录下,编译运行(注意要把log4j-1.2.7.jar包含入类路径中),程序输出如下:
0 [main] DEBUG TestLog4J - Start of main()
10 [main] INFO TestLog4J - Just testing a log message with priority set to INFO
20 [main] WARN TestLog4J - Just testing a log message with priority set to WARN
30 [main] ERROR TestLog4J - Just testing a log message with priority set to ERROR
30 [main] FATAL TestLog4J - Just testing a log message with priority set to FATAL
40 [main] DEBUG TestLog4J - Testing a log message use a alternate form
50 [main] DEBUG TestLog4J - End of main().
首先解释一下上面输出结果的意义。第一个数字是指程序开始运行到运行该日志语句所经历的毫秒数(用来做一点运行效率分析也不错),“[main]”是日志事件发生的线程,随后的“DEBUG”、“INFO”等信息是相应日志信息的优先级别,“TestLog4”是当前Logger的实例名,最后是日志信息。
在这段程序中,使用了Log4J提供的一个基本配置类BasicConfigurator对Log4J进行初始化。但在实际使用时通常不这么做,因为这多少有点“硬”编码。今后如果要修改Log4J的配置,就需要修改、重新编译代码,这通常不是大家所希望的。通常,我们都提供一个名为 log4j.properties的文件,在第一次调用到Log4J时,Log4J会在类路径中定位这个文件,并读入这个文件完成的配置。这个配置文件告诉Log4J以什么样的格式、把什么样的信息、输出到什么地方。我们来看一个简单的log4j.properties配置文件的示例,代码如下:
log4j.rootLogger=DEBUG, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern= %-4r [%t] %-5p %c %x - %m%n
把上面的内容存储为log4j.properties,并放到和TestLog4J.class同一目录下(当然也可以放到其它任何目录,只要该目录被包含到类路径中即可)。具体这些配置文件中每行的意义,在以后章节会有详细的说明,现在可以先跳过。现在你可以注释掉上面程序中的 “BasicConfigurator. configure();”语句,然后使用log4j.properties属性文件完成Log4J的配置,重新编译、运行,就得到和上面一样的结果。
这样做有什么好处呢?现在就初步领略一些Log4J的灵活、强大功能。比如系统要上线了,希望输出一些警告和错误信息,这时仅需要修改 log4j.properties文件中的“log4j.rootCategory=DEBUG, A1”即可,然后设置日志输出的最低级别是WARN,设置为“log4j.root Category=WARN, A1”。此时不需要修改任何代码,重新运行系统,输出结果就变成了:
20 [main] WARN TestLog4J - Just testing a log message with priority set to WARN
30 [main] ERROR TestLog4J - Just testing a log message with priority set to ERROR
30 [main] FATAL TestLog4J - Just testing a log message with priority set to FATAL
原理分析
Log4J有三个主要部件,它们是记录器(Loggers)、输出源(Appenders)和布局(Logouts)。记录器按照布局中指定的格式把日志信息写入一个或多个输出源。输出源可以是控制台、文本文件、XML文件或Socket,甚至还可以把信息写入到Windows事件日志或通过电子邮件发送,这都需要相应的类来处理,这些相关的类是ConsoleAppender、FileAppender、SocketAppender、 NtEventLogAppender和JMSAppender。
记录器(Logger)
首先让我们看Logger类,代码如下:
package org.apache.log4j;
public class Logger {
//创建和恢复方法
public static Logger getRootLogger();
public static Logger getLogger(String name);
public static Logger getLogger(Class clazz);
// 打印方法
public void debug(Object message);
public void info(Object message);
public void warn(Object message);
public void error(Object message);
public void fatal(Object message);
// 常用打印方法
public void log(Level l, Object message);
}
从这段代码中可以看出Logger的基本使用。首先需要获取一个Logger对象,获取Logger对象的语句为:
Logger logger = Logger.getLogger(JavaLoggingExample.class.getName());
有了这个Logger对象,就可以在需要的地方方便地输出日志信息。对于这些信息是否输出、输出的格式等,都可以通过配置文件方便地配置,而不需要修改代码,这就是Log4J带来的方便之处。
记录器的层次结构
使用Log4J的Logger.getLogger()方法时会得到一个Logger的实例。如果一个应用中包含了上千个类,那么也几乎需要上千个 Logger实例。如何对这上千个Logger实例进行方便地配置,就是一个很重要的问题。Log4J采用了一种树状的继承层次巧妙地解决了这个问题。在 Log4J中Logger是具有层次关系的。它有一个共同的根,位于最上层,其它Logger遵循类似包的层次,比如:
static Logger root = Logger.getRootLogger();
static Logger log1 = Logger.getLogger("org");
static Logger log2 = Logger.getLogger("org.javaresearch");
static Logger log3 = Logger.getLogger("org.javaresearch.log4j.TestLog4J");
上面代码中,log1是log2的父亲,是log3的祖先,而root是所有log1、log2、log3的祖先,它们都从root中继承。所以,一般情况下,仅需要配置好rootLogger,其它子记录器都会从中继承rootLogger的配置。如果修改了rootLogger的配置,其它所有的子记录器也会继承这种变化。这样就大大地方便了配置。现在回头看看在“快速入门”中的配置文件,我们仅配置了rootLogger,就可以控制所有的 Logger的行为。
级别(Level)
Log4J中的一个核心概念是日志级别是有序的。Log4J内置了5种日志级别为:
DEBUG < INFO < WARN < ERROR < FATAL
右边的级别比左边的高。每一个Logger实例都有一个日志级别,上面的5种输出方法就是对应于5种不同级别的日志请求。比如,如果c是一个Logger 实例,c.info("some information")就是一个INFO级别的日志请求。一个日志请求会不会输出,取决于该Logger实例的日志级别和该日志请求级别的比较。规则如下:
假如在一个级别为p的Logger实例中发生一个级别为q的日志请求,则当q >= p时请求才会启用。
我们先来看实例2代码如下:
// 得到一个logger 实例 "com.foo"
Logger logger = Logger.getLogger("com.foo")
// 现在设置logger的级别,但正常情况是不需要刻意设置lgger级别的,因为它已经在配置文件中完成了
logger.setLevel(Level.INFO);
Logger barlogger = Logger.getLogger("com.foo.Bar");
//因为 WARN >= INFO,这个请求是可以实现的
logger.warn("Low fuel level.");
// 因为DEBUG < INFO,所以这个请求是无法实现的
logger.debug("Starting search for nearest gas station.");
// logger实例"com.foo.Bar"将从"com.foo"继承级别,这样,因为INFO >=
INFO,所以可以实现下面的请求
barlogger.info("Located nearest gas station.");
//因为DEBUG < INFO,这个请求是不能实现的
barlogger.debug("Exiting gas station search");
布局(Layout)
Log4J采用类似C语言中的printf函数的打印格式格式化日志信息,打印参数见表1如下:
%m 输出代码中指定的消息
%p 输出优先级,即DEBUG,INFO,WARN,ERROR,FATAL
%r 输出自应用启动到输出该log信息耗费的毫秒数
%c 输出所属的类目,通常就是所在类的全名
%t 输出产生该日志事件的线程名
%n 输出一个回车换行符,Windows平台为“/r/n”,Unix平台为“/n”
%d 输出日志时间点的日期或时间,默认格式为ISO8601,也可以在其后指定格式,比如:%d{yyy MMM dd HH:mm:ss,SSS},输出类似:2002年10月18日 22:10:28,921
%l 输出日志事件的发生位置,包括类目名、发生的线程,以及在代码中的行数。举例:Testlog4.main(TestLog4.java:10)
基本应用
Log4J的配置
现在来看log4j.properties配置文件的意义。第一行指定了根Logger的级别是DEBUG,并将此指定输出到A1。A1就是第二行定义的 org.apache.log4j.ConsoleAppender,此行表示将A1输出到控制台。第三行规定了输出到A1的格式为 org.apache.log4j.PatternLayout。第四行规定了输出到A1格式的转换模式为 org.javaresearch.log4j.TestLog4J。
很多成熟的服务器类的软件日志信息会输出到控制台,同时输出到日志文件备查。使用Log4J可以在不改变任何代码的情况下,仅通过修改配置文件就可以轻松地完成这项功能。相关配置文件如下:
#### Use two appenders, one to log to console, another to log to a file
log4j.rootCategory=debug, stdout, R
# Print only messages of priority WARN or higher for your category
log4j.category.your.category.name=WARN
#### First appender writes to console
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
# Pattern to output the caller's file name and line number.
log4j.appender.stdout.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n
#### Second appender writes to a file
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=example.log
# Control the maximum log file size
log4j.appender.R.MaxFileSize=100KB
# Archive log files (one backup file here)
log4j.appender.R.MaxBackupIndex=1
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%p %t %c - %m%n
这个配置文件指定了两个输出源stdout和R。前者把日志信息输出到控制台,后者是一个轮转日志文件。最大的文件是100KB,当一个日志文件达到最大尺寸时,Log4J会自动把example.log重命名为example.log.1,然后重建一个新的example.log文件,依次轮转。
在Web应用中使用
在Web应用中,应该在哪儿对Log4J进行配置呢?首先要明确,Log4J必须在应用的其它代码执行前完成初始化。因为Servlet是在Web服务器启动时立即装入的,所以,在Web应用中一般使用一个专门的Servlet来完成Log4J的配置,并保证在web.xml的配置中,这个Servlet 位于其它Servlet之前。下面是一个例子,代码如下:
package org.javaresearch.log4j;
import java.io.*;
import javax.servlet.*;
import org.apache.log4j.*;
public class Log4JInit extends HttpServlet {
public void init() throws ServletException {
String prefix = getServletContext().getRealPath("/");
String file = getServletConfig().getInitParameter("log4j-config-file");
// 从Servlet参数读取log4j的配置文件
if (file != null) {
PropertyConfigurator.configure(prefix + file);
}
}
public void doGet(HttpServletRequest request,HttpServletResponse response)
throws IOException, ServletException {}
public void doPost(HttpServletRequest request,HttpServletResponse response)
throws IOException, ServletException {}
}
<servlet>
<servlet-name>log4jinit</servlet-name>
<servlet-class>org.javaresearch.log4j.Log4JInit</servlet-class>
<init-param>
<param-name>log4j-config-file </param-name>
<param-value>/properties/log4j.properties</param-value>
</init-param>
<load-on-startup>1</load-on-startup>
</servlet>
注意:上面的load-on-startup应设为1,以便在Web容器启动时即装入该Servlet。log4j.properties文件放在根的properties子目录中,也可以把它放在其它目录中。应该把.properties文件集中存放,这样方便管理。
高级话题
性能
在记录一些日志信息时,会一定程度地影响系统的运行效率,这时日志工具是否高效就是一个关键。Log4J的首要设计目标就是高效,一些关键组件都重写过很多次以不断提高性能。根据Log4J项目小组的报告,在AMD Duron 800MHz + JDK1.3.1的环境下,Log4J判断一条日志语句是否需要输出仅需要5纳秒。实际的日志语句执行的也非常快速,从使用SimpleLayout的 21微秒(几乎与System.out.println一样快),到使用TTCCLayout的37微秒不等。
嵌套诊断环境NDC
在多用户并发的环境下,通常是由不同的线程分别处理不同的客户端请求。此时要在日志信息中区分出不同的客户端,你可以为每一个线程生成一个Logger,从而从一堆日志信息中区分出哪些信息是属于哪个线程的,但这种方式并不高效。Log4J巧妙地使用了Neil Harrison提出的“NDC(嵌套诊断环境)”机制来解决这个问题。Log4J为同一类别的线程生成一个Logger,多个线程共享使用,而它仅在日志信息中添加能够区分不同线程的信息。NDC是什么?举例来说,如果一个Servlet接到并发请求时,为每一个客户端创建一个新的线程,然后分配一个用于保存该请求上下文的NDC堆栈。该上下文可能是发出请求的主机名、IP地址或其它任何可以用于标识该请求的信息。这样,由于不同的客户端处理线程具有不同的NDC堆栈,即使这个Servlet同时生成多个线程处理不同的请求,这些日志信息仍然可以区分出来,就好像Log4J为每一个线程都单独生成了一个 Logger实例一样。在Log4J中是通过org.apache.log4j.NDC实现这种机制的。使用NDC的方法也很简单,步骤如下:
1. 在进入一个环境时调用NDC.push(String),然后创建一个NDC;
2. 所做的日志操作输出中包括了NDC的信息;
3. 离开该环境时调用NDC.pop方法;
4. 当从一个线程中退出时调用NDC.remove方法,以便释放资源。
下面是一个模拟记录来自不同客户端请求事件的例子,代码如下:
import org.apache.log4j.Logger;
import org.apache.log4j.NDC;
public class TestNDC {
static Logger log = Logger.getLogger(TestNDC.class.getName());
public static void main(String[] args) {
log.info("Make sure %x is in your layout pattern!");
// 从客户端获得IP地址的例子
String[] ips = {"192.168.0.10","192.168.0.27"};
for (int i = 0; i < ips.length ; i++) // 模拟一个运行方法
{
// 将IP放进 NDC中
NDC.push(ips[i]);
log.info("A NEW client connected, who's ip should appear in this log message.");
NDC.pop();
}
NDC.remove();
log.info("Finished.");
}
}
注意配置文件中的布局格式中一定要加上%x。系统输出如下:
INFO - Make sure %x is in your layout pattern!
INFO 192.168.0.10 - A NEW client connected, who's ip should appear in this log
message.
INFO 192.168.0.27 - A NEW client connected, who's ip should appear in this log
message.
INFO - Finished.
使用Log4J还是JDK logging API
从JDK 1.4.0开始,引入了java.util.logging包。虽然Log4J小组曾竭力游说JCP(Java Community Process)采用Log4J作为JDK 1.4的“标准”日志API,虽然最终因Sun的日志API规范的负责人Graham Hamilton的一句“Merlin的开发已经到了最后阶段,这时不允许再对主要API做出改变”而没有被采纳,但Log4J还是对新的日志API产生了重要影响。那么,我们到底应该采用Log4J还是java.util.logging包呢?下面仅对两者做一简单的比较。
1. Log4J更加成熟,从1999年10月开始至今已经有3年的时间,并且已经在许多项目中有着成熟的应用。而JDK中的logging包是在1.4之后才引入的,并且不能运行于JDK 1.3之前的版本。Log4J则可以良好地运行于JDK 1.1之后的所有版本。
2. Log4J已经被移植到多种环境下,包括log4c(C)、log4cpp(C++)、log4perl(Perl)、log4net(.net)等。在这些环境下,可以感受到几乎一致的配置和使用方式。这是JDK中的logging API所不能比拟的。
3. Log4J还具有更加强力的格式化系统,可以使记录输出时实现简单的模式。但是,它不会增加类而导致格式化工具的扩展。众多的附加程序和处理器使得Log4J数据包成为一个绝佳的选择,所有你所需要的都可能加以实现。
4. Log4J在性能上做了最大的优化。
Logging API对于简单的使用是足够的,但它缺少了许多Log4J所具有的功能。所以,如果你需要一个强力的logging机制,就应坚持使用Log4J;而如果只是需要一些简单的控制或文件记录,那么可以使用已经内建在JDK之中的logging API。
虽然Log4J和JDK logging API是一种竞争关系,但在logging API还在JCP中讨论(JSR47)时,两者之间就已经开始相互影响了。
FAQ
1. 如何让Log4J使用指定的配置文件
在启动你的应用时植入系统属性。例如,可以把上面的log4j.properties文件放到/properties的相对路径下,并改名为log.properties,此时如果让Log4J能够找到这个配置文件并正确地初始化,需要这样运行程序:
D:/../java -Dlog4j.configuration=. /properties/log.properties YourAppName
为什么一定要使用系统属性,而不在配置文件中指定呢?很显然,如果把它写入配置文件,那么,Log4J读到它时已经迟了。
2. 如何查看到Log4J的配置过程
可以类似1中的那样,设置系统属性log4j.debug=true,从而打开Log4J的Verbose模式,此时会输出Log4J的初始化过程,这样就会对Log4J的启动有一个更详细的了解。下面是Log4J启动信息的一个示例:
log4j: Trying to find [log4j.xml] using context classloader
sun.misc.Launcher$AppClassLoader@92e78c.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$ExtClassLoader@9fbe93class
loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader
sun.misc.Launcher$AppClassLoader@92e78c.
log4j: Using URL [file:/D:/java/logging/src/log4j.properties] for automatic log4j
configuration.
log4j: Reading configuration from URL file:/E:/java/logging/src/log4j.properties
log4j: Parsing for [root] with value=[DEBUG, A1].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "A1".
log4j: Parsing layout options for "A1".
log4j: Setting property [conversionPattern] to [%d %l %-5p %c [%t] - %m%n].
log4j: End of parsing for "A1".
log4j: Parsed "A1" options.
log4j: Finished configuring.
...... // 下面就是应用的日志信息,省略