【IT168 技术文章】

        为什么多线程很复杂?

　　如果程序同时运行在多个线程上，每个线程的日志信息可能会交织在一起。凡是尝试过从 15 个交织的线程的输出中读取信息的人都明白我所指的是什么!此外，代码还可能经常运行在多台机器上的分布式系统中。如果对所有组件使用相同的跟踪系统，您将被迫协调系统的多个输出，从而可能面临内部时钟不同步的风险。(这最后一个问题实在是一件麻烦事情。设想这样的情况，您读取整个跟踪信息，却没有意识到客户端机器上的时间戳整整要比服务器上的对应时间戳早 20 秒!)

　　清单 1 是单个程序产生的跟踪信息的一个例子，该程序使用简单的输出来运行，输出中使用了时间戳和消息。它非常类似您采用自行设计的日志记录基础结构时可能看到的输出。

　　清单 1. 一个简单应用程序的跟踪信息

　　这看起来似乎全都很简单。但是现在看一下清单 2，它显示了应用程序扩展至同时运行五个线程时所发生的情况。

　　清单 2. 一个多线程应用程序的跟踪信息

　　那么那五个线程中哪个线程出了问题呢?这是一个简单的例子，更好的跟踪语句将帮助确定问题根源，但是您可以看出，当只有时间戳来指导您时，仅只是五个线程的输出就是多么令人混淆。所有线程的输出乱七八糟地混合在一起，而定时问题意味着输出语句不是以相对的线程顺序出现的。

　　那么您如何自己做出改进呢?关键就是使用 唯一标识符。您需要使用与其输出相关联的唯一 ID 来标记每个线程。这样将允许基于该唯一 ID 来过滤最终的跟踪信息。log4j 默认情况下输出类似如下的消息：

　　注意它已经包括了一个线程 ID。但是正如您从中可以看出的，输出的布局在默认情况下不是很理想，它丢失了时间戳，而我认为时间戳正是任何日志记录系统的至关重要的元素。

　　幸运的是，log4j 具有一个非常好的特性，它将帮您纠正这个问题：用户可以通过配置一个文件来确定跟踪输出的新布局。我将对本文例子使用的文件如清单 3 所示。

　　清单 3. 示例 log4j 配置文件

　　其中的有些(或许是全部)初看起来可能相当含糊。让我们逐行地研究它以理解其语法。第一行定义了连接到根日志记录器的日志记录器。之后配置的两项是 stdout 和 R 。您可以看到 stdout 与一个 ConsoleAppender 关联，然后被赋予一个 PatternLayout 。然后是使用两个变量来定义模式;您将在后面看到那些变量如何与输出的各部分相关联。基本上，随后是对 R 完成相同的设置--只不过它是一个文件目的地(file appender)。它接受一个文件名称、一个最大尺寸以及一个备份索引。备份索引告诉它要保留日志多长时间，因此在到达最大尺寸时，该日志将被重命名，一个全新的日志文件又开始了。正如您可以看到的， PatternLayout 因而是相同的。

　　这个配置存储在一个名为 log4j.properties的文件中，我只是将它作为一个参数传递给代码。除了定义首选的布局外，它还指定了同时使用控制台日志 和日志文件。日志文件被设置为仅增长到 1000 KB;届时，旧的日志将变成 example.log.1，同时创建新的日志。您可以使用 MaxBackupIndex 参数来指定要保留的历史日志数量。这是非常容易使用的;最好的是，您可以在以后改变配置文件以适应自己的需要，而无需改动代码。

　　如果使用清单 3 中的配置文件来运行 log4j，结果将输出如下：

　　这样就为您提供了一个日期戳、日志记录级别指标、线程 ID、当前所在的行号，以及日志消息。然而，正如您可能猜想得那样，所使用的线程号仅在单个 JVM 内才是唯一的。当您将每次 JVM 运行所产生的跟踪数据分离开来时，这是很理想的;但是如果您希望查看同时在单独的 JVM 中运行的多个实例，那么添加另一个唯一的 ID 来确保您没有把线程弄乱，这样将是有帮助的。为此，一种简单的方法就是仅在派生某个线程时才生成一个随机数，并将该随机数追加到所有输出行上。

　　然而，您可能认为这样是不必要的，并且只会给跟踪输出添加更多混乱，因为您必须将该随机数作为一个参数传递给被调用的程序。(如果不希望传入一个参数，您可以添加一个方法，客户机可以使用该方法来查询被调用程序的线程 ID。这样您至少有了将客户机线程与被调用线程联系起来的途径。虽然这样做并不容易，但是不失为一种有效的办法。) 我个人认为，不仅只是运行多个线程，而且还要完成客户机程序的一个单独实例，然后就能够将所有客户机跟踪与后端的活动联系起来，或许还可以将客户机信息组合到一个文件中，这样将是有帮助的。向执行线程分配随机数将帮助您实现这个目的。因而在这个例子中，我将使用这种随机数技术。(后面我还将展示这种技术所允许的一些很棒的事情。)

　　有了这个附加的内容，典型的跟踪输出将类似如下：

　　[Thread-1] 是 JVM 线程 ID，它是当您调用 Thread.currentThread.getName() 时所得到的内容。 [-992285010] 就是您的随机数。它(我希望如此)在跟踪的范围内将是唯一的，而线程 ID 和随机数的组合应该能够满足跨越多个 JVM 的唯一性。

　　例子应用程序

　　现在是该引入一些例子来展示产生前述内容的基本调用的时候了。在这个例子场景中，一个多线程的客户机应用程序从每个线程调用一个 EJB 组件 log1Bean 。 相应地，这个 bean 又对位于一个不同的服务器上的第二个 EJB 组件 log2Bean 发出调用。通过这种方式，您可以让代码在三台机器上针对多个线程运行。这样做的目的是准确跟踪每个阶段究竟发生了什么事情。

　　正如您可以看到的，我们最终将面对一个在其中执行跟踪的相当复杂的环境。当时还是让我们不厌其烦地到达那一步吧。清单 4 是针对客户机代码的第一个步骤。它是一个实现 Runnable 接口的类，并运行一些除了使用 log4j 外，其他什么也不做的线程。

　　清单 4. 使用 log4j 的简单客户机类

　　上面的代码相当长，但当前没有做多少事情。它主要作用只是展示线程的基础结构。 main() 方法更是没有做什么事情。请注意 logger 命令;当前，这只是您可以执行的日志记录级别的一个例子。我使用了一个相当标准的集合：

　　info 将表示诸如方法入口/出口之类的东西，以及关于成功操作的更新。

　　debug 倾向于用于表示诸如变量在某个时刻的值等内容。

　　warn 可用于表示某些可重试的事情已失败的情形;例如，它可以警告某个连接在第一次尝试时没有成功建立，并且系统将再次尝试。

　　error 表示某个地方出错了。

　　fatal 表示某个错误阻止了进一步的处理。

　　然而务必要记住，如何将输出划分为这些类别取决于您自己的决定。您要确保预先考虑到了这一点：如果有多个人负责编写向相同日志写出内容的代码，那么每个人都知道该准则是很重要的。您不会希望因为将某种类型的消息放进混合的类别中而丢失系统的值。我建议编写一个关于打算如何对特定内容分类的指南。

　　如果希望在自己的应用程序中使用这些方法，那么并没有什么真正神秘和奇妙的东西需要添加到您的代码中。您只需把对 System.out.println() (或您用于输出跟踪数据的其他任何机制)的调用替换为对相应 log4j 方法的调用。

　　您应该记录可能会遇到的尽可能多的内容。当您真正进入调试过程时，不可避免会希望获得您无法获得的那一部分信息。如果性能是一个问题，那就应该谨慎考虑所记录的内容以及如何记录它。Log4j 提供了一些关于其性能影响的文档，以及如何改进性能的方法。一般来讲，打开日志记录时的性能和关闭日志记录时的性能之间是一种折中关系。

　　需要记录的有用信息如下：

　　方法的入口/出口

　　入口处的变量值

　　在何处对外发出调用(对于远程调用)

　　每个远程调用之前和之后的时间(时间戳可以显示该调用花了多长时间)

　　每个线程的开始和结束

　　请使用以下命令行来运行具有几个线程的示例代码：

　　您将看到自己得到了简洁的输出块。每个线程的输出独立于其他线程的输出，因为在执行期间没有可用于分割时间选择的办法。当您开始进行第一次 EJB 查找时，这种情况将会改变。