简介：大多数 Java 程序员都使用某种跟踪系统来跟踪开发中的代码的潜在 错 误和问题。然而，多线程和多平台环境可能产生大量莫名其妙的跟踪数据。在本 文中，软件工程师 Daniel Would 提供了一些技巧，帮助您理解复杂应用程序中 产生的跟踪数据。您将了解如何使用开放源代码的日志记录软件包 log4j 来生 成 包含丰富信息的日志文件。您还将看到如何使用标准 UNIX shell 命令来挖掘您 需要的信息数据。
Scott Clee 在“ Use a consistent trace system for easier debugging ” 一文中向您展示了如何在自定义的类中跟踪和进行日志记录，从而提供跨越所有 应用程序的一致跟踪方法。这种方法对于运行在单个线程上的单独应用程序很理 想，但是当情况变得更复杂时，您很快就会发现自己面对着一大堆跟踪数据，对 如何跟踪实际发生的事情毫无线索。
成功的跟踪需要两个要素。第一个要素是输出有用的足够信息。第二个要素 是 以您能够获得所需信息的方式输出信息。毕竟，您可能会输出一大堆整体上无法 阅读和不可理解的数据。 因而，本文将划分为两个部分：一个部分集中于产生 跟 踪数据，另一个部分集中于以特定方式查询结果信息。
在日志/跟踪方面，您有两个选择。您当然可以采用“自行设想”的技术；也 可以采用预先准备好的支持类（专有的和免费的均可），后者提供了广泛的功能 。免费实现的一个例子就是 log4j；它已得到很好的证明、快速并且通用。它提 供了全面的基础结构和易于理解的配置。因而，我选择了它作为本文例子的基础 。在本文中，我将指导您使用 log4j，并将它应用于一个多线程、多平台的工作 例子。
Log4j 很容易设置：您所需做的就是向应用程序的每个部分提供 log4j JAR 文件，从而开始日志记录（请参阅 下载和安装 log4j）。log4j 的使用已在其 文 档中作了说明，还有一些文章研究了它的基本用法（请参阅 参考资料 以获得相 关链接）。在本文中，我将讨论在复杂环境中进行日志记录时需要考虑的事情， 并展示如何在一个工作例子的环境中最有效地使用 log4j 中提供的功能。我还 将 展示如何在收集到日志信息之后挖掘信息。即使拥有世界上最好的计划，在一个 大型日志文件中查找所需要的信息也可能仍然是一个耗时和棘手的过程。
为什么多线程很复杂？
如果程序同时运行在多个线程上，每个线程的日志信息可能会交织在一起。 凡 是尝试过从 15 个交织的线程的输出中读取信息的人都明白我所指的是什么！此 外，代码还可能经常运行在多台机器上的分布式系统中。如果对所有组件使用相 同的跟踪系统，您将被迫协调系统的多个输出，从而可能面临内部时钟不同步的 风险。（这最后一个问题实在是一件麻烦事情。设想这样的情况，您读取整个跟 踪信息，却没有意识到客户端机器上的时间戳整整要比服务器上的对应时间戳早 20 秒！）
清单 1 是单个程序产生的跟踪信息的一个例子，该程序使用简单的输出来运 行，输出中使用了时间戳和消息。它非常类似您采用自行设计的日志记录基础结 构时可能看到的输出。
清单 1. 一个简单应用程序的跟踪信息
(12:01:02) Starting(12:01:02) initializing variables(12:01:03) making call to db(12:01:04) got value 'A'(12:01:05) setting new value to db(12:01:05) done
这看起来似乎全都很简单。但是现在看一下清单 2，它显示了应用程序扩展 至 同时运行五个线程时所发生的情况。
清单 2. 一个多线程应用程序的跟踪信息
(12:01:02) Starting(12:01:02) Starting(12:01:02) Starting(12:01:02) Starting(12:01:02) initializing variables(12:01:02) initializing variables(12:01:03) making call to db(12:01:03) making call to db(12:01:03) initializing variables(12:01:03) initializing variables(12:01:03) making call to db(12:01:03) making call to db(12:01:03) Starting(12:01:04) got value 'A'(12:01:04) initializing variables(12:01:04) got value 'B'(12:01:04) got value 'X'(12:01:04) got value '3'(12:01:04) making call to db(12:01:05) setting new value to db(12:01:05) setting new value to db(12:01:05) got value 'A'(12:01:05) setting new value to db(12:01:05) setting new value to db(12:01:05) done(12:01:05) setting new value to db(12:01:05) done(12:01:05) done(12:01:05) FAILED!!!(12:01:05) done
那么那五个线程中哪个线程出了问题呢？这是一个简单的例子，更好的跟踪 语 句将帮助确定问题根源，但是您可以看出，当只有时间戳来指导您时，仅只是五 个线程的输出就是多么令人混淆。所有线程的输出乱七八糟地混合在一起，而定 时问题意味着输出语句不是以相对的线程顺序出现的。
那么您如何自己做出改进呢？关键就是使用 唯一标识符。您需要使用与其输 出相关联的唯一 ID 来标记每个线程。这样将允许基于该唯一 ID 来过滤最终的 跟踪信息。log4j 默认情况下输出类似如下的消息：
153 [Thread-1] INFO demo.logger.sample.SampleCode - Program Running
注意它已经包括了一个线程 ID。但是正如您从中可以看出的，输出的布局在 默认情况下不是很理想，它丢失了时间戳，而我认为时间戳正是任何日志记录系 统的至关重要的元素。
幸运的是，log4j 具有一个非常好的特性，它将帮您纠正这个问题：用户可 以 通过配置一个文件来确定跟踪输出的新布局。我将对本文例子使用的文件如清单 3 所示。
清单 3. 示例 log4j 配置文件
log4j.rootLogger=debug, stdout, Rlog4j.appender.stdout=org.apache.log4j.ConsoleAppenderlog4j.a p pender.stdout.layout=org.apache.log4j.PatternLayout# Pattern to output the caller's file name and line number.log4j.appender.stdout.layout.ConversionPattern=%d %5p [%t] (%F:%L) - %m% nlog4j.appender.R=org.apache.log4j.RollingFileAppenderlog4j.ap p ender.R.File=example.loglog4j.appender.R.MaxFileSize=1000KB# Keep one backup filelog4j.appender.R.MaxBackupIndex=1log4j.appender.R.layout=o r g.apache.log4j.PatternLayoutlog4j.appender.R.layout.ConversionPatt e rn=%d %5p [%t] (%F:%L) - %m%n
其中的有些（或许是全部）初看起来可能相当含糊。让我们逐行地研究它以 理 解其语法。第一行定义了连接到根日志记录器的日志记录器。之后配置的两项是 stdout 和 R 。您可以看到 stdout 与一个 ConsoleAppender 关联，然后被赋 予 一个 PatternLayout 。然后是使用两个变量来定义模式；您将在后面看到那些 变 量如何与输出的各部分相关联。基本上，随后是对 R 完成相同的设置–只不过 它 是一个文件目的地（file appender）。它接受一个文件名称、一个最大尺寸以 及 一个备份索引。备份索引告诉它要保留日志多长时间，因此在到达最大尺寸时， 该日志将被重命名，一个全新的日志文件又开始了。正如您可以看到的， PatternLayout 因而是相同的。
这个配置存储在一个名为 log4j.properties的文件中，我只是将它作为一个 参数传递给代码。除了定义首选的布局外，它还指定了同时使用控制台日志 和 日 志文件。日志文件被设置为仅增长到 1000 KB；届时，旧的日志将变成 example.log.1，同时创建新的日志。您可以使用 MaxBackupIndex 参数来指定 要 保留的历史日志数量。这是非常容易使用的；最好的是，您可以在以后改变配置 文件以适应自己的需要，而无需改动代码。
如果使用清单 3 中的配置文件来运行 log4j，结果将输出如下：
2004-01-24 15:00:23,714 INFO [Thread-1] (SampleCode.java:67) - Program Running
这样就为您提供了一个日期戳、日志记录级别指标、线程 ID、当前所在的行 号，以及日志消息。然而，正如您可能猜想得那样，所使用的线程号仅在单个 JVM 内才是唯一的。当您将每次 JVM 运行所产生的跟踪数据分离开来时，这是 很 理想的；但是如果您希望查看同时在单独的 JVM 中运行的多个实例，那么添加 另 一个唯一的 ID 来确保您没有把线程弄乱，这样将是有帮助的。为此，一种简单 的方法就是仅在派生某个线程时才生成一个随机数，并将该随机数追加到所有输 出行上。
然而，您可能认为这样是不必要的，并且只会给跟踪输出添加更多混乱，因 为 您必须将该随机数作为一个参数传递给被调用的程序。（如果不希望传入一个参 数，您可以添加一个方法，客户机可以使用该方法来查询被调用程序的线程 ID 。 这样您至少有了将客户机线程与被调用线程联系起来的途径。虽然这样做并不容 易，但是不失为一种有效的办法。） 我个人认为，不仅只是运行多个线程，而 且 还要完成客户机程序的一个单独实例，然后就能够将所有客户机跟踪与后端的活 动联系起来，或许还可以将客户机信息组合到一个文件中，这样将是有帮助的。 向执行线程分配随机数将帮助您实现这个目的。因而在这个例子中，我将使用这 种随机数技术。（后面我还将展示这种技术所允许的一些很棒的事情。）
有了这个附加的内容，典型的跟踪输出将类似如下：
[Thread-1] 是 JVM 线程 ID，它是当您调用 Thread.currentThread.getName() 时所得到的内容。 [-992285010] 就是您的 随 机数。它（我希望如此）在跟踪的范围内将是唯一的，而线程 ID 和随机数的组 合应该能够满足跨越多个 JVM 的唯一性。
例子应用程序
现在是该引入一些例子来展示产生前述内容的基本调用的时候了。在这个例 子 场景中，一个多线程的客户机应用程序从每个线程调用一个 EJB 组件 log1Bean 。 相应地，这个 bean 又对位于一个不同的服务器上的第二个 EJB 组件 log2Bean 发出调用。通过这种方式，您可以让代码在三台机器上针对多个线程 运 行。这样做的目的是准确跟踪每个阶段究竟发生了什么事情。
正如您可以看到的，我们最终将面对一个在其中执行跟踪的相当复杂的环境 。 当时还是让我们不厌其烦地到达那一步吧。清单 4 是针对客户机代码的第一个 步 骤。它是一个实现 Runnable 接口的类，并运行一些除了使用 log4j 外，其他 什 么也不做的线程。（注意我对所有代码例子使用了 Eclipse 开发环境。我已在 参考资料小节中包括了一些指向 Eclipse 和 Eclipse 插件的链接。）
清单 4. 使用 log4j 的简单客户机类
/** Created on 24-Jan-04** To change the template for this generated file go to* Window>Preferences>Java>Code Generation>Code and Comments*/package demo.logger.sample;import java.util.Random;import java.util.VecTor;import org.apache.log4j.Logger;import org.apache.log4j.PropertyConfiguraTor;/*** @author wouldd** To change the template for this generated type comment go to* Window>Preferences>Java>Code Generation>Code and Comments*/public class SampleCode implements Runnable{ private static ThreadGroup myGroup = new ThreadGroup("group1"); private static Logger logger = Logger.getLogger(SampleCode.class); // //invoked as: //java demo.logger.sample.SampleCode // public static void main(String[] args) { PropertyConfiguraTor.configure (args[1]); logger.info("About to start threads"); VecTor threads = new VecTor(); int thrdsCount = Integer.parseInt(args[0]); for (int i = 0; i < thrdsCount; i++) { SampleCode sc1 = new SampleCode(); threads.add(sc1); } } public SampleCode() { threadStarter(); return; } public void threadStarter() { int sleepTime; try { Thread aThread = new Thread(myGroup, this); aThread.setPriority(Thread.NORM_PRIORITY); java.util.Random rnd = new Random(); // //start threads at random intervals up to 1000 ms // sleepTime = (int) (rnd.nextInt(1000)); Thread.sleep (sleepTime); Thread.yield(); aThread.start(); return; } catch (java.lang.InterruptedException e) { } } public void run(){ // //create random id for this thread // Random rnd = new Random(); int rndid = rnd.nextInt(); logger.info("[" +rndid +"]"+ " Program Running"); logger.debug("[" +rndid +"]" + " Debug message!!"); logger.warn("[" +rndid +"]" + " Warning this is a warning"); logger.error("[" +rndid +"]" + " Error Message!!"); logger.fatal("[" +rndid +"]" + "A Non-Fatal FATAL message!!"); }}
上面的代码相当长，但当前没有做多少事情。它主要作用只是展示线程的基 础 结构。 main() 方法更是没有做什么事情。请注意 logger 命令；当前，这只是 您可以执行的日志记录级别的一个例子。我使用了一个相当标准的集合：
info 将表示诸如方法入口/出口之类的东西，以及关于成功操作的更新。
debug 倾向于用于表示诸如变量在某个时刻的值等内容。
warn 可用于表示某些可重试的事情已失败的情形；例如，它可以警告某个连 接在第一次尝试时没有成功建立，并且系统将再次尝试。
error 表示某个地方出错了。
fatal 表示某个错误阻止了进一步的处理。
然而务必要记住，如何将输出划分为这些类别取决于您自己的决定。您要确 保 预先考虑到了这一点：如果有多个人负责编写向相同日志写出内容的代码，那么 每个人都知道该准则是很重要的。您不会希望因为将某种类型的消息放进混合的 类别中而丢失系统的值。我建议编写一个关于打算如何对特定内容分类的指南。
如果希望在自己的应用程序中使用这些方法，那么并没有什么真正神秘和奇 妙 的东西需要添加到您的代码中。您只需把对 System.out.println() （或您用于 输出跟踪数据的其他任何机制）的调用替换为对相应 log4j 方法的调用。
您应该记录可能会遇到的尽可能多的内容。当您真正进入调试过程时，不可 避 免会希望获得您无法获得的那一部分信息。如果性能是一个问题，那就应该谨慎 考虑所记录的内容以及如何记录它。Log4j 提供了一些关于其性能影响的文档， 以及如何改进性能的方法。一般来讲，打开日志记录时的性能和关闭日志记录时 的性能之间是一种折中关系。
需要记录的有用信息如下：
方法的入口/出口
入口处的变量值
在何处对外发出调用（对于远程调用）
每个远程调用之前和之后的时间（时间戳可以显示该调用花了多长时间）
每个线程的开始和结束
请使用以下命令行来运行具有几个线程的示例代码：
java demo.logger.sample.SampleCode 10
您将看到自己得到了简洁的输出块。每个线程的输出独立于其他线程的输出 ， 因为在执行期间没有可用于分割时间选择的办法。当您开始进行第一次 EJB 查 找 时，这种情况将会改变。
添加 EJB 组件
现在您将创建客户机将要调用的 EJB 组件。它们将做一些非常有限的处理。 第一个 bean 将基于一个随机数做出是否调用第二个 bean 的选择。因而，其中 一些线程将调用第二个 bean，而有些却不会这样。这样将会给跟踪输出添加一 些 变化，从而说明这种技术的强大能力。
要做的第一件事情是在一个系统属性中设置日志记录器。设置方法将因为用 于 部署 EJB 组件的服务器不同而异。我选择了一个名为 log4j.prop 的设置；这 个 设置指向一个包含此设置的文件。这对于您正在创建的两个 EJB 组件都是一样 的 。
清单 5 包含了第一个示例 EJB 组件。
注意这些清单是不完整的：我删除了所有的空方法（ ejbRemove() ，等等） 。显然，您需要那些方法才能执行代码，但是这里列出它们没有意义。
清单 5. log1Bean
package demo.logger.sample;/*** Bean implementation class for Enterprise Bean: log1*/import java.rmi.RemoteException;import java.util.Properties;import java.util.Random;import javax.naming.InitialContext;import javax.rmi.PortableRemoteObject;import org.apache.log4j.Logger;import org.apache.log4j.PropertyConfiguraTor;public class log1Bean implements javax.ejb.SessionBean { private static Logger logger = Logger.getLogger(log1Bean.class); private static String ejbHomeLocation = "ejb/log2Home"; private javax.ejb.SessionContext mySessionCtx; /** * ejbCreate */ public void ejbCreate() throws javax.ejb.CreateException { // //pickup the location of the property file as a system property // Properties sp = System.getProperties(); String propFile = sp.getProperty("log4j.props"); PropertyConfiguraTor.configure (propFile); logger.info("Logger started for log1Bean, bean created"); String ejbHomeLocation = sp.getProperty ("log2.jndi"); } public boolean doTest(int id) { //this method takes the id of the thread that called it to continue use in its own logging //it will roll a random number, and choose to lookup another EJB or not boolean result = true; logger.info("[" +id +"]"+ " Started doTest method in log1Bean"); Random rand = new Random (); int choice = rand.nextInt(10); logger.debug ("[" +id +"]"+ " Random choice is " + choice); if (choice <=5) { // //link to ejb2 // try{ InitialContext ic = new InitialContext (); Object r = ic.lookup(ejbHomeLocation); if (or != null) { // Narrow the return object to the Home class type log2Home home = (log2Home) PortableRemoteObject.narrow(or, log2Home.class); // Create an EJB object instance using the home interface. try{ log2 lb2 = home.create (); // Invoke the method if (lb2.doTest(id) == true){ logger.info("[" + id +"]"+ " Execution ran successfully"); } }catch (RemoteException re){ logger.fatal("[" +id + "]" + " Failure to create remote EJB " + re); } } }catch(Exception e){ logger.fatal("[" +id +"]"+ " Failure when looking up log2Bean " + e); e.printStackTrace(); } }else{ // //state that you've gone nowhere and return // logger.info("[" +id +"]"+ " Path ends at Log1Bean"); } return result; }}
清单 6 包含了第二个 bean。它与第一个非常类似；它只是返回已经到达某 次 给定的执行过程的结尾这个事实。
清单 6. log2Bean
package demo.logger.sample;import java.util.Properties;import org.apache.log4j.Logger;import org.apache.log4j.PropertyConfiguraTor;/*** Bean implementation class for Enterprise Bean: log2*/public class log2Bean implements javax.ejb.SessionBean { private static Logger logger = Logger.getLogger(log1Bean.class); private javax.ejb.SessionContext mySessionCtx; /** * ejbCreate */ public void ejbCreate() throws javax.ejb.CreateException { // //pickup the location of the property file as a system property // Properties sp = System.getProperties(); String propFile = sp.getProperty ("log4jejb2.props"); PropertyConfiguraTor.configure (propFile); logger.info("Logger started for log2Bean, bean created"); } public boolean doTest(int id) { //this method takes the id of the thread that called it to continue use in its own logging //it will roll a random number, and choose to lookup another EJB or not boolean result = true; logger.info("[" +id +"]"+ " Started doTest method in log2Bean"); logger.info("[" +id +"]"+ " Path ends in Log2Bean"); return result; }}
第一个 bean log1Bean 就它应该简单地返回还是连接到第二个 bean 做出随 机的选择。它通过系统属性获得 log4j 属性文件和第二个 bean 的位置，您可 以 为自己的系统适当地设置这些属性。
我最初将两个 bean 都设置在相同的服务器上，这样只是为了进行测试。后 来 我改为使用一个多服务器设置。显而易见，为了在第二个服务器上查找，您需要 提供正确的系统属性以使得查找工作能够进行。当一切都在相同的服务器上时， 全部三个执行程序都可以使用同一个日志文件，这样您就会得到一个不错的组合 日志。但是从现在起，我将假设您在单独的机器上运行程序，因而最终会得到三 个单独的日志文件。
运行方案
如果您是在家自行测试，现在就是安装 EJB 组件和设置系统属性以挑选配置 文件和组件位置的时间了。具体的方式各不相同，取决于您的应用程序服务器选 择。您应该能够取得前面提供的属性文件，并为每个 EJB 组件创建该文件的一 个 拷贝。（这基本上涉及为每个 EJB 组件准备完全相同的文件；在我的例子中， 我 在一台机器上运行两个示例服务器，因此我必须修改属性文件以指向两个独立但 是完全相同的文件。）一旦所有组件都已正常运行，您只需更新客户机来实际执 行查找，并调用第一个 EJB 组件。完成这个工作所需要的代码是相当标准的； 您 可以通过 参考资料 小节下载完整的客户机代码。（如果无法让组件彼此找到对 方，您可能会发现阅读我以前的文章 “Navigate the JNDI maze” 会有所帮助； 请参阅 参考资料 以获得相关链接。）
下面让我们通过以下命令行来运行具有 50 个线程的客户机：
Java demo.logger.sample.SampleCode 50 /home/wouldd/JavaWork/workspace/LoggerDemo/log4j.properties thisNode/servers/server1/ejb/log1Home
您不需要所有那些线程，不过这样您会看到自己创建的日志记录系统的强大 能 力。
如果是在家自行测试，您应该看到在系统的每个部分的属性文件中所指定的 目 录中生成的日志文件；如果没有指定目录，它将出现在每个进程的当前文件夹中 。或者，您可以检查可通过 参考资料 找到的文件中的输出。观察一下这些文件 ，您将看到类似如下的行：
2004-01-24 15:00:23,714 INFO [Thread-1] (SampleCode.java:67) - [-992285010] Program Running
这里您可以看到不同的线程标识符等内容。根据行号（在日志所来自的文件 的 名称后面），您可以看到各种情况是如何从客户机到两个 EJB 组件的过程中发 生 的。
下面让我们实际深入研究一下这些日志，看看 log4j 能告诉您哪些有趣的信 息。
日志文件包含了什么秘密？
注意：如果您没有使用 Linux 或其他 UNIX，您将在本节中使用的控制台命 令 可能不容易获得。不过您可以使用 Cygwin 来提供一个 Microsoft Windows 下 面 的 UNIX 命令控制台（请参阅 参考资料 以获得链接。）
为了查看所有日志文件的完整内容，您可以使用以下命令：
cat *.log
当然，这假设您是在包含那些文件的目录中，并且它们以 .log 为扩展名。 （ 这是我使用的惯例，不过当您在属性文件中指定日志文件时，可以通过任何方式 来命名它们。）当然，那样命名将无法给人以深刻的印象。不过可以尝试输入以 下命令：
cat *.log | sort
您将得到类似清单 7 所示的输出。
清单 7. 排序后的日志数据
2004-01-25 18:18:28,000 INFO [Thread-4] (SampleCode.java:109) - [-1278270939] Calling Create on log1Home2004-01-25 18:18:28,316 INFO [Thread-4] (SampleCode.java:114) - [-1278270939] Execution ran successfully2004-01-25 18:18:28,585 INFO [Thread-5] (SampleCode.java:92) - [-1756513822] Program Running2004-01-25 18:18:28,586 INFO [Thread-5] (SampleCode.java:98) - [- 1756513822] Obtaining Initial context
突然之间，所有那些时间戳把一切都安排得有序了——或者说它们至少应该 这 样。这个时候您可以弄清用于运行测试的机器是否全都与该时间一致，并且如果 运气好的话，您还会进一步了解把来自多个平台的跟踪数据放到一块的复杂性。 如果明显看出系统的时间不同步，那么我建议您研究一下可用于同步它们的各种 可用途径（请参阅 参考资料以获得链接）。如果没有事情似乎在错误的时间发 生 ，那么尝试弄清跟踪数据中发生了什么是相当困难的。
因此现在您有一个包含形形色色的内容的巨大清单（按年代顺序排列）。您 可 以逐个地扫描其中的每项内容，但是所谓的“易于阅读”很难实现。例如，编号 为 24 的线程究竟发生了什么事情呢？您希望完全扫描一遍该文件来弄清楚吗？ 下面让我们尝试一种更容易的方法：
cat *.log | grep Thread-24
这个命令将显示客户机的第 24 个线程产生的输出。现在您可能认识到添加 唯 一的线程 ID 是一个多好的主意。当然，必须通过一个参数将它传递给 EJB 组 件 是一件痛苦的事情，但是现在您能够容易地将它挑选出来（ 代表随 机 ID 编号）：
cat *.log | sort | grep
就像是魔力一样，您得到了第 24 个线程所触发的完整执行路径的有序输出 ， 它看起来应该类似清单 8。您可以看到它是在 log1Bean 处停止还是继续，并且 您不必对混乱的其他跟踪点排序。
清单 8. 第 24 个线程所触发的完整执行路径
example.log:2004-01-25 18:18:50,445 INFO [Thread-24] (SampleCode.java:92) - [-1242473967] Program Runningexample.log:2004-01-25 18:18:50,446 INFO [Thread-24] (SampleCode.java:98) - [-1242473967] Obtaining Initial contextexample.log:2004-01-25 18:18:50,521 INFO [Thread-24] (SampleCode.java:103) - [-1242473967] Narrowing home interface for log1Beanexample.log:2004-01-25 18:18:50,522 INFO [Thread-24] (SampleCode.java:109) - [-1242473967] Calling Create on log1Homeexample.log:2004-01-25 18:18:50,535 INFO [Thread-24] (SampleCode.java:114) - [-1242473967] Execution ran sucesfullyexamplelog2bean.log:2004-01-25 18:18:50,528 INFO [ORB.thread.pool : 0] (log1Bean.java:65) - [-1242473967] Started doTest method in log1Beanexamplelog2bean.log:2004-01-25 18:18:50,529 DEBUG [ORB.thread.pool : 0] (log1Bean.java:69) - [- 1242473967] Random choice is 5examplelog2bean.log:2004-01-25 18:18:50,530 INFO [ORB.thread.pool : 0] (log2Bean.java:60) - [- 1242473967] Started doTest method in log2Beanexamplelog2bean.log:2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0] (log2Bean.java:61) - [-1242473967] Path ends in Log2Beanexamplelog2bean.log:2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0] (log1Bean.java:91) - [-1242473967] Execution ran sucesfully
注意每行中的第一部分信息指出了该行所来自的文件。
下面让我们看看您可以使用跟踪信息来做的一些更灵活的事情。请尝试执行 以 下命令：
cut -d '[' -f3 example.log | cut -d ']' -f1 | uniq
这个命令将提取运行期间所使用的所有唯一 ID。它本身并不是很有趣，但是 您可以结合其他命令来使用它，从而的到有趣的结果：
cut -d '[' -f3 example.log | cut -d ']' -f1 | uniq | awk '{system("grep -e " $1 " *.log > log"$1 ".txt")}'
这个难懂的行基本上是在说：“从我的客户机日志文件中取出所有的唯一 ID ，然后将每个 ID 与关联的日志存储在一个 log.txt格式的文件中。 ” 这样将给您带来 50 个文件，每个文件仅包含一个线程的跟踪数据。因此上 面的第 24 个线程的输出例子将存储在一个名为 log-1242473967.txt的文件中 ，文件名中的数字就是唯一的 ID。
其他日志选项
有必要阅读一下 log4j 文档以检查它提供的各种可能性。其中一个日志记录 选项就是 Log FacTor 5 控制台。这是一个显示源代码的一个层次结构树（基于 包名称）的 GUI；与选定的树组件相关联的日志显示在主窗口中。
您还可以选择通过网络进行日志记录。通过将一个日志记录服务器设置在选 定的端口上，您可以让多台机器向该连接写出日志，而不是（或另外还要）写出 到一个本地日志文件。这对于在一个地方集中收集所有跟踪数据可能是有用的。 我的首选方式是为每台机器保留单独的文件；您能够容易地查询它们或将它们组 合起来。然而，通过研究 log4j 提供的所有功能，您也许会找到更适合需要的 许多选项。
这是非常酷的，不过要记住：只有当您准备了恰当的信息时，那些命令才会 给您提供这样强大的能力。如果没有时间戳，您就不能有效地排序；如果没有线 程 ID 和唯一编号，您就不能如此整洁地分类信息。您给自己提供的唯一最强大 的帮助是沿着执行路径传递的 ID。您也许不喜欢添加用于日志记录的参数，但 是这样会给您带来大量强有力的选项。
如果您认为这些命令行看起来很复杂，我应该在写下它们之前很快指出我从 不尝试使用它们：我只是知道这些命令存在，并且能够迅速应用那些用于创建它 们的原理，这本身是非常有用的。我要向所有命令行高手道歉，他们能够容易地 确定一种异常整洁的方式来达到相同的结果。
您当然可以选择仅记录某些级别的输出，但是我的选择是记录所有内容，并 使用过滤技术在任何给定的时间提取我需要的信息。因而对于一次给定的运行， 如果您打算改变想要记录的详细级别，那么您只需改变过滤器。只需使用 grep 来提取具有 INFO或 FATAL或其他任何内容的行。
创建系统快照
那么，您希望对日志信息做其他哪些事情呢？ 您可以在 log4j 提供的控制 台上实时查看它；您可以组合多个文件，以及将单独的线程输出分离到单独的文 件中。但是如何查看多平台环境中同一时刻发生的所有事情呢？好了，时间戳是 一个美妙的东西。只需使用一个简单的命令，您就可以看到指定时刻产生的所有 输出：
cat *.log | grep 18:18:50 | sort
这个命令的输出类似清单 8。
清单 8. 指定时刻的跟踪数据
2004-01-25 18:18:50,445 INFO [Thread-45](SampleCode.java:92) - [-1242473967] Program Running2004-01-25 18:18:50,446 INFO [Thread-45](SampleCode.java:98) - [-1242473967] Obtaining Initial context2004-01-25 18:18:50,521 INFO [Thread-45](SampleCode.java:103) - [-1242473967] Narrowing home interface for log1Bean2004-01-25 18:18:50,522 INFO [Thread-45](SampleCode.java:109) - [-1242473967] Calling Create on log1Home2004-01-25 18:18:50,528 INFO [ORB.thread.pool : 0](log1Bean.java:65) - [-1242473967] Started doTest method in log1Bean2004-01-25 18:18:50,529 DEBUG [ORB.thread.pool : 0](log1Bean.java:69) - [-1242473967] Random choice is 52004-01-25 18:18:50,530 INFO [ORB.thread.pool : 0](log2Bean.java:60) - [-1242473967] Started doTest method in log2Bean2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0](log1Bean.java:91) - [-1242473967] Execution ran sucesfully2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0](log2Bean.java:61) - [-1242473967] Path ends in Log2Bean2004-01-25 18:18:50,535 INFO [Thread-45](SampleCode.java:114) - [-1242473967] Execution ran sucesfully2004-01-25 18:18:50,865 INFO [Thread-46](SampleCode.java:92) - [-1490252259] Program Running2004-01-25 18:18:50,872 INFO [Thread-46](SampleCode.java:98) - [-1490252259] Obtaining Initial context2004-01-25 18:18:50,874 INFO [Thread-46](SampleCode.java:103) - [-1490252259] Narrowing home interface for log1Bean2004-01-25 18:18:50,875 INFO [Thread-46](SampleCode.java:109) - [-1490252259] Calling Create on log1Home2004-01-25 18:18:50,880 INFO [ORB.thread.pool : 0](log1Bean.java:65) - [-1490252259] Started doTest method in log1Bean2004-01-25 18:18:50,881 DEBUG [ORB.thread.pool : 0](log1Bean.java:69) - [-1490252259] Random choice is 92004-01-25 18:18:50,881 INFO [ORB.thread.pool : 0](log1Bean.java:108) - [-1490252259] Path ends at Log1Bean2004-01-25 18:18:50,886 INFO [Thread-46](SampleCode.java:114) - [-1490252259] Execution ran sucesfully
您可以看到自己得到了一个排序的清单，其中列出了在指定的某一秒 （18:18:50）发生的所有事情。当然，您可以定义所需要的时间范围。这个命令 将提供所有系统中发生的每件事情；如果您乐意，还可以对单个应用程序进行日 志记录（不管它们是否相关），以及对每个日子文件执行搜索，从而获得所有系 统在给定时刻发生的事情的快照。
您还可以重用我前面给出的一个命令来截取在此时间期限中得到处理的所有 唯一 ID，并为每个线程生成单独的线程日志。这样允许您有效地来回跟踪在给 定的时间段内发生的每个事件。如果您无法完全理解这点，可以看看下面这个命 令：
cat *.log | grep 18:18:50 | sort | cut -d '[' -f3 | cut -d ']'-f1 | uniq | awk '{system("grep -e " $1 " *.log > log"$1 ".txt")}'
这无疑是一个难懂的行，不过请考虑一下它给您提供了什么信息：对于您选 择为其提供日志的任意多的系统，您可以指定任意时刻的任何快照，然后获得一 个单独的线程日志，其中显示那些进程在其生命周期中都做了些什么。实际上， 与前面那样得到 50 个文件不同，您 仅得到在指定的时间段中记录了一些输出 的那些线程的文件。如果想要尝试理解出故障时事件之间的复杂交互，那么这听 起来好像是一些相当有帮助的信息。
当然，如果您还回想得起的话，我实际上仅只是捕捉在我指定的时间期限内 做了日志记录的线程。那些当时正在运行但是没有做日志记录的线程又怎么样呢 ？下面是另外一些可以帮助您的命令。如果觉得烦的话，我或许可以把所有这些 内容全都拼接到一个臃肿的命令中；但是相反，下面是三个单独的命令，它们基 本上是检查某个特定时间段之前和之后的所有唯一编号，然后检查具有这些编号 的线程是否在之前 和之后记录了日志（因而这些线程也在该时间段内运行）。
awk '{ if ($2 beforelog.txtawk '{ if ($2 > "18:18:51") print }' *.log | cut-d '[' -f3 | cut -d ']' -f1 | uniq > afterlog.txtcat beforelog.txt | awk '{system("grep " $1 " afterlog.txt")}'| uniq | awk '{system("grep -e " $1 " *.log > log"$1 ".txt")}'
同样地，这里的每个文件包含前面使用第 24 个线程的例子所示的线程的历 史记录。但是现在您看到了在您感兴趣的时间期限内执行的所有那些线程（即使 那些线程碰巧没有在该期限中记录日志）的文件。
结束语
我甚至还没有谈及您可以配置 log4j 的令人吃惊的方式；有许多文章研究了 如何继承日志设置，以及调整相关设置以便不同的包类可以使用不同的日志记录 级别。但是我已介绍的内容将帮助您学会如何使用 log4j；您现在还应该具有了 很好的日志记录习惯，它们将帮助您收集特别是复杂系统的丰富信息。并且这适 用于需要进行日志记录的 任何程序。不管使用 log4j 与否，只要坚持使用相同 的信息和布局，您仍然能够使用我讲述过的 UNIX 命令来完成所有的数据挖掘。
下面总结一些关键要点：
从一开始就计划日志记录。事后添加日志记录功能要困难 得多，并且您在最 初开始调试代码时就会需要它。
挑选一种满足需要的机制，但是不要让事情变得对您更复杂。如果其他某人 编写了一个免费、开放源代码、得到维护、执行良好、特性丰富的选项……那么 请 使用它。
应该预先决定将要使用何种日志级别，并确保编程团队中的每个人都知道您 希望他们使用的约定。
如果您是在从头开始，那就添加端到端的处理 ID。通过您的程序传递这些 ID 确实是值得付出的努力。
了解 UNIX 文本处理命令的强大能力。我在本文中是从命令行使用它们的， 不过您也可以在脚本中使用它们。
您应该记录可能会遇到的尽可能多的内容，不过不要忘了保持性能。特别要 注意对远程调用进行日志记录，以及在线程分支、开始和结束的位置进行日志记 录。日志中的信息越多，您所能实现数据挖掘就越强有力。
年轻是我们唯一拥有权利去编织梦想的时光
