技术开发 频道

多线程、多平台环境中的跟踪

  注意:如果您没有使用 Linux 或其他 UNIX,您将在本节中使用的控制台命令可能不容易获得。不过您可以使用 Cygwin 来提供一个 Microsoft Windows 下面的 UNIX 命令控制台。

  为了查看所有日志文件的完整内容,您可以使用以下命令:

1 cat *.log
2

  当然,这假设您是在包含那些文件的目录中,并且它们以 .log 为扩展名。(这是我使用的惯例,不过当您在属性文件中指定日志文件时,可以通过任何方式来命名它们。)当然,那样命名将无法给人以深刻的印象。不过可以尝试输入以下命令:

1 cat *.log | sort
2

  您将得到类似清单 7 所示的输出。

  清单 7. 排序后的日志数据

1 2004-01-25 18:18:28,000  INFO [Thread-4]
2   (SampleCode.java:109) - [-1278270939] Calling Create on log1Home
3 2004-01-25 18:18:28,316  INFO [Thread-4]
4   (SampleCode.java:114) - [-1278270939] Execution ran successfully
5 2004-01-25 18:18:28,585  INFO [Thread-5]
6   (SampleCode.java:92) - [-1756513822] Program Running
7 2004-01-25 18:18:28,586  INFO [Thread-5]
8   (SampleCode.java:98) - [-1756513822] Obtaining Initial context

  突然之间,所有那些时间戳把一切都安排得有序了——或者说它们至少应该这样。这个时候您可以弄清用于运行测试的机器是否全都与该时间一致,并且如果运气好的话,您还会进一步了解把来自多个平台的跟踪数据放到一块的复杂性。如果明显看出系统的时间不同步,那么我建议您研究一下可用于同步它们的各种可用途径。如果没有事情似乎在错误的时间发生,那么尝试弄清跟踪数据中发生了什么是相当困难的。

  因此现在您有一个包含形形色色的内容的巨大清单(按年代顺序排列)。您可以逐个地扫描其中的每项内容,但是所谓的“易于阅读”很难实现。例如,编号为 24 的线程究竟发生了什么事情呢?您希望完全扫描一遍该文件来弄清楚吗?下面让我们尝试一种更容易的方法:

1 cat *.log | grep Thread-24
2

  这个命令将显示客户机的第 24 个线程产生的输出。现在您可能认识到添加唯一的线程 ID 是一个多好的主意。当然,必须通过一个参数将它传递给 EJB 组件是一件痛苦的事情,但是现在您能够容易地将它挑选出来( 代表随机 ID 编号):

1 cat *.log | sort | grep <id>
2

  就像是魔力一样,您得到了第 24 个线程所触发的完整执行路径的有序输出,它看起来应该类似清单 8。您可以看到它是在 log1Bean 处停止还是继续,并且您不必对混乱的其他跟踪点排序。

  清单 8. 第 24 个线程所触发的完整执行路径

1 example.log:2004-01-25 18:18:50,445  INFO [Thread-24]
2   (SampleCode.java:92) - [-1242473967] Program Running
3 example.log:2004-01-25 18:18:50,446  INFO [Thread-24]
4   (SampleCode.java:98) - [-1242473967] Obtaining Initial context
5 example.log:2004-01-25 18:18:50,521  INFO [Thread-24]
6   (SampleCode.java:103) - [-1242473967] Narrowing home interface for log1Bean
7 example.log:2004-01-25 18:18:50,522  INFO [Thread-24]
8   (SampleCode.java:109) - [-1242473967] Calling Create on log1Home
9 example.log:2004-01-25 18:18:50,535  INFO [Thread-24]
10   (SampleCode.java:114) - [-1242473967] Execution ran sucesfully
11 examplelog2bean.log:2004-01-25 18:18:50,528  INFO [ORB.thread.pool : 0]
12   (log1Bean.java:65) - [-1242473967] Started doTest method in log1Bean
13 examplelog2bean.log:2004-01-25 18:18:50,529 DEBUG [ORB.thread.pool : 0]
14   (log1Bean.java:69) - [-1242473967] Random choice is 5
15 examplelog2bean.log:2004-01-25 18:18:50,530  INFO [ORB.thread.pool : 0]
16   (log2Bean.java:60) - [-1242473967] Started doTest method in log2Bean
17 examplelog2bean.log:2004-01-25 18:18:50,531  INFO [ORB.thread.pool : 0]
18   (log2Bean.java:61) - [-1242473967] Path ends in Log2Bean
19 examplelog2bean.log:2004-01-25 18:18:50,531  INFO [ORB.thread.pool : 0]
20   (log1Bean.java:91) - [-1242473967] Execution ran sucesfully
21

  注意每行中的第一部分信息指出了该行所来自的文件。

  下面让我们看看您可以使用跟踪信息来做的一些更灵活的事情。请尝试执行以下命令:

1 cut -d '[' -f3 example.log | cut -d ']' -f1 | uniq
2

  这个命令将提取运行期间所使用的所有唯一 ID。它本身并不是很有趣,但是您可以结合其他命令来使用它,从而的到有趣的结果:

1 cut -d '[' -f3 example.log | cut -d ']' -f1 | uniq | awk
2   '{system("grep -e " $1 " *.log > log"$1 ".txt")}'
3

  这个难懂的行基本上是在说:“从我的客户机日志文件中取出所有的唯一 ID,然后将每个 ID 与关联的日志存储在一个 log.txt 格式的文件中。” 这样将给您带来 50 个文件,每个文件仅包含一个线程的跟踪数据。因此上面的第 24 个线程的输出例子将存储在一个名为 log-1242473967.txt 的文件中,文件名中的数字就是唯一的 ID。

  这是非常酷的,不过要记住:只有当您准备了恰当的信息时,那些命令才会给您提供这样强大的能力。如果没有时间戳,您就不能有效地排序;如果没有线程 ID 和唯一编号,您就不能如此整洁地分类信息。您给自己提供的唯一最强大的帮助是沿着执行路径传递的 ID。您也许不喜欢添加用于日志记录的参数,但是这样会给您带来大量强有力的选项。

  如果您认为这些命令行看起来很复杂,我应该在写下它们之前很快指出我从不尝试使用它们:我只是知道这些命令存在,并且能够迅速应用那些用于创建它们的原理,这本身是非常有用的。我要向所有命令行高手道歉,他们能够容易地确定一种异常整洁的方式来达到相同的结果。

  您当然可以选择仅记录某些级别的输出,但是我的选择是记录所有内容,并使用过滤技术在任何给定的时间提取我需要的信息。因而对于一次给定的运行,如果您打算改变想要记录的详细级别,那么您只需改变过滤器。只需使用 grep 来提取具有 INFO 或 FATAL 或其他任何内容的行。

  创建系统快照

  那么,您希望对日志信息做其他哪些事情呢? 您可以在 log4j 提供的控制台上实时查看它;您可以组合多个文件,以及将单独的线程输出分离到单独的文件中。但是如何查看多平台环境中同一时刻发生的所有事情呢?好了,时间戳是一个美妙的东西。只需使用一个简单的命令,您就可以看到指定时刻产生的所有输出:

1 cat *.log | grep 18:18:50 | sort
2

  这个命令的输出类似清单 9。

  清单 9. 指定时刻的跟踪数据        您可以看到自己得到了一个排序的清单,其中列出了在指定的某一秒(18:18:50)发生的所有事情。当然,您可以定义所需要的时间范围。这个命令将提供所有系统中发生的每件事情;如果您乐意,还可以对单个应用程序进行日志记录(不管它们是否相关),以及对每个日子文件执行搜索,从而获得所有系统在给定时刻发生的事情的快照。

1 2004-01-25 18:18:50,445  INFO [Thread-45]
2   (SampleCode.java:92) - [-1242473967] Program Running
3 2004-01-25 18:18:50,446  INFO [Thread-45]
4   (SampleCode.java:98) - [-1242473967] Obtaining Initial context
5 2004-01-25 18:18:50,521  INFO [Thread-45]
6   (SampleCode.java:103) - [-1242473967] Narrowing home interface for log1Bean
7 2004-01-25 18:18:50,522  INFO [Thread-45]
8   (SampleCode.java:109) - [-1242473967] Calling Create on log1Home
9 2004-01-25 18:18:50,528  INFO [ORB.thread.pool : 0]
10   (log1Bean.java:65) - [-1242473967] Started doTest method in log1Bean
11 2004-01-25 18:18:50,529 DEBUG [ORB.thread.pool : 0]
12   (log1Bean.java:69) - [-1242473967] Random choice is 5
13 2004-01-25 18:18:50,530  INFO [ORB.thread.pool : 0]
14   (log2Bean.java:60) - [-1242473967] Started doTest method in log2Bean
15 2004-01-25 18:18:50,531  INFO [ORB.thread.pool : 0]
16   (log1Bean.java:91) - [-1242473967] Execution ran sucesfully
17 2004-01-25 18:18:50,531  INFO [ORB.thread.pool : 0]
18   (log2Bean.java:61) - [-1242473967] Path ends in Log2Bean
19 2004-01-25 18:18:50,535  INFO [Thread-45]
20   (SampleCode.java:114) - [-1242473967] Execution ran sucesfully
21 2004-01-25 18:18:50,865  INFO [Thread-46]
22   (SampleCode.java:92) - [-1490252259] Program Running
23 2004-01-25 18:18:50,872  INFO [Thread-46]
24   (SampleCode.java:98) - [-1490252259] Obtaining Initial context
25 2004-01-25 18:18:50,874  INFO [Thread-46]
26   (SampleCode.java:103) - [-1490252259] Narrowing home interface for log1Bean
27 2004-01-25 18:18:50,875  INFO [Thread-46]
28   (SampleCode.java:109) - [-1490252259] Calling Create on log1Home
29 2004-01-25 18:18:50,880  INFO [ORB.thread.pool : 0]
30   (log1Bean.java:65) - [-1490252259] Started doTest method in log1Bean
31 2004-01-25 18:18:50,881 DEBUG [ORB.thread.pool : 0]
32   (log1Bean.java:69) - [-1490252259] Random choice is 9
33 2004-01-25 18:18:50,881  INFO [ORB.thread.pool : 0]
34   (log1Bean.java:108) - [-1490252259] Path ends at Log1Bean
35 2004-01-25 18:18:50,886  INFO [Thread-46]
36   (SampleCode.java:114) - [-1490252259] Execution ran sucesfully
37

  您还可以重用我前面给出的一个命令来截取在此时间期限中得到处理的所有唯一 ID,并为每个线程生成单独的线程日志。这样允许您有效地来回跟踪在给定的时间段内发生的每个事件。如果您无法完全理解这点,可以看看下面这个命令:

1 cat *.log | grep 18:18:50 | sort | cut -d '[' -f3 | cut -d ']'
2   -f1 | uniq | awk '{system("grep -e " $1 " *.log > log"$1 ".txt")}'
3

  这无疑是一个难懂的行,不过请考虑一下它给您提供了什么信息:对于您选择为其提供日志的任意多的系统,您可以指定任意时刻的任何快照,然后获得一个单独的线程日志,其中显示那些进程在其生命周期中都做了些什么。实际上,与前面那样得到 50 个文件不同,您 仅得到在指定的时间段中记录了一些输出的那些线程的文件。如果想要尝试理解出故障时事件之间的复杂交互,那么这听起来好像是一些相当有帮助的信息。

  当然,如果您还回想得起的话,我实际上仅只是捕捉在我指定的时间期限内 做了日志记录的线程。那些当时正在运行但是没有做日志记录的线程又怎么样呢?下面是另外一些可以帮助您的命令。如果觉得烦的话,我或许可以把所有这些内容全都拼接到一个臃肿的命令中;但是相反,下面是三个单独的命令,它们基本上是检查某个特定时间段之前和之后的所有唯一编号,然后检查具有这些编号的线程是否在之前 和之后记录了日志(因而这些线程也在该时间段内运行)。

1 awk '{ if ($2 < "18:18:50") print }' *.log | cut
2   -d '[' -f3 | cut -d ']' -f1  | uniq > beforelog.txt
3 awk '{ if ($2 > "18:18:51") print }' *.log | cut
4   -d '[' -f3 | cut -d ']' -f1  | uniq > afterlog.txt
5 cat beforelog.txt | awk '{system("grep " $1 " afterlog.txt")}'
6   | uniq | awk '{system("grep -e " $1 " *.log > log"$1 ".txt")}'
7

  同样地,这里的每个文件包含前面使用第 24 个线程的例子所示的线程的历史记录。但是现在您看到了在您感兴趣的时间期限内执行的所有那些线程(即使那些线程碰巧没有在该期限中记录日志)的文件。

  结束语

  我甚至还没有谈及您可以配置 log4j 的令人吃惊的方式;有许多文章研究了如何继承日志设置,以及调整相关设置以便不同的包类可以使用不同的日志记录级别。但是我已介绍的内容将帮助您学会如何使用 log4j;您现在还应该具有了很好的日志记录习惯,它们将帮助您收集特别是复杂系统的丰富信息。并且这适用于需要进行日志记录的 任何程序。不管使用 log4j 与否,只要坚持使用相同的信息和布局,您仍然能够使用我讲述过的 UNIX 命令来完成所有的数据挖掘。

  下面总结一些关键要点:

  从一开始就计划日志记录。事后添加日志记录功能要困难 得多,并且您在最初开始调试代码时就会需要它。

  挑选一种满足需要的机制,但是不要让事情变得对您更复杂。如果其他某人编写了一个免费、开放源代码、得到维护、执行良好、特性丰富的选项……那么请 使用它。

  应该预先决定将要使用何种日志级别,并确保编程团队中的每个人都知道您希望他们使用的约定。

  如果您是在从头开始,那就添加端到端的处理 ID。通过您的程序传递这些 ID 确实是值得付出的努力。

  了解 UNIX 文本处理命令的强大能力。我在本文中是从命令行使用它们的,不过您也可以在脚本中使用它们。

  您应该记录可能会遇到的尽可能多的内容,不过不要忘了保持性能。特别要注意对远程调用进行日志记录,以及在线程分支、开始和结束的位置进行日志记录。日志中的信息越多,您所能实现数据挖掘就越强有力。

       相关下载: logdemo.ear 

0
相关文章