kapok

大家在编程时经常不可避免地要使用到一些日志操作，比如开发阶段的调试信息、运行时的日志记录及审计。调查显示，日志代码占代码总量的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.
...... // 下面就是应用的日志信息，省略