簡介：大多數 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, R
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.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% n
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.ap p ender.R.File=example.log
log4j.appender.R.MaxFileSize=1000KB
# Keep one backup file
log4j.appender.R.MaxBackupIndex=1
log4j.appender.R.layout=o r g.apache.log4j.PatternLayout
log4j.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 <threads> <logconfigfile>
//
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 or = 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 log1Home
2004-01-25 18:18:28,316 INFO [Thread-4]
(SampleCode.java:114) - [-1278270939] Execution ran successfully
2004-01-25 18:18:28,585 INFO [Thread-5]
(SampleCode.java:92) - [-1756513822] Program Running
2004-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> 代表隨 機 ID 編號）：
cat *.log | sort | grep <id>
就像是魔力一樣，您得到了第 24 個線程所觸發的完整執行路徑的有序輸出 ， 它看起來應該類似清單 8。您可以看到它是在 log1Bean 處停止還是繼續，並且 您不必對混亂的其他跟蹤點排序。
清單 8. 第 24 個線程所觸發的完整執行路徑
example.log:2004-01-25 18:18:50,445 INFO [Thread-24]
(SampleCode.java:92) - [-1242473967] Program Running
example.log:2004-01-25 18:18:50,446 INFO [Thread-24]
(SampleCode.java:98) - [-1242473967] Obtaining Initial context
example.log:2004-01-25 18:18:50,521 INFO [Thread-24]
(SampleCode.java:103) - [-1242473967] Narrowing home interface for log1Bean
example.log:2004-01-25 18:18:50,522 INFO [Thread-24]
(SampleCode.java:109) - [-1242473967] Calling Create on log1Home
example.log:2004-01-25 18:18:50,535 INFO [Thread-24]
(SampleCode.java:114) - [-1242473967] Execution ran sucesfully
examplelog2bean.log:2004-01-25 18:18:50,528 INFO [ORB.thread.pool : 0]
(log1Bean.java:65) - [-1242473967] Started doTest method in log1Bean
examplelog2bean.log:2004-01-25 18:18:50,529 DEBUG [ORB.thread.pool : 0]
(log1Bean.java:69) - [- 1242473967] Random choice is 5
examplelog2bean.log:2004-01-25 18:18:50,530 INFO [ORB.thread.pool : 0]
(log2Bean.java:60) - [- 1242473967] Started doTest method in log2Bean
examplelog2bean.log:2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0]
(log2Bean.java:61) - [-1242473967] Path ends in Log2Bean
examplelog2bean.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<id>.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 Running
2004-01-25 18:18:50,446 INFO [Thread-45]
(SampleCode.java:98) - [-1242473967] Obtaining Initial context
2004-01-25 18:18:50,521 INFO [Thread-45]
(SampleCode.java:103) - [-1242473967] Narrowing home interface for log1Bean
2004-01-25 18:18:50,522 INFO [Thread-45]
(SampleCode.java:109) - [-1242473967] Calling Create on log1Home
2004-01-25 18:18:50,528 INFO [ORB.thread.pool : 0]
(log1Bean.java:65) - [-1242473967] Started doTest method in log1Bean
2004-01-25 18:18:50,529 DEBUG [ORB.thread.pool : 0]
(log1Bean.java:69) - [-1242473967] Random choice is 5
2004-01-25 18:18:50,530 INFO [ORB.thread.pool : 0]
(log2Bean.java:60) - [-1242473967] Started doTest method in log2Bean
2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0]
(log1Bean.java:91) - [-1242473967] Execution ran sucesfully
2004-01-25 18:18:50,531 INFO [ORB.thread.pool : 0]
(log2Bean.java:61) - [-1242473967] Path ends in Log2Bean
2004-01-25 18:18:50,535 INFO [Thread-45]
(SampleCode.java:114) - [-1242473967] Execution ran sucesfully
2004-01-25 18:18:50,865 INFO [Thread-46]
(SampleCode.java:92) - [-1490252259] Program Running
2004-01-25 18:18:50,872 INFO [Thread-46]
(SampleCode.java:98) - [-1490252259] Obtaining Initial context
2004-01-25 18:18:50,874 INFO [Thread-46]
(SampleCode.java:103) - [-1490252259] Narrowing home interface for log1Bean
2004-01-25 18:18:50,875 INFO [Thread-46]
(SampleCode.java:109) - [-1490252259] Calling Create on log1Home
2004-01-25 18:18:50,880 INFO [ORB.thread.pool : 0]
(log1Bean.java:65) - [-1490252259] Started doTest method in log1Bean
2004-01-25 18:18:50,881 DEBUG [ORB.thread.pool : 0]
(log1Bean.java:69) - [-1490252259] Random choice is 9
2004-01-25 18:18:50,881 INFO [ORB.thread.pool : 0]
(log1Bean.java:108) - [-1490252259] Path ends at Log1Bean
2004-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 < "18:18:50") print }' *.log | cut
-d '[' -f3 | cut -d ']' -f1 | uniq > beforelog.txt
awk '{ if ($2 > "18:18:51") print }' *.log | cut
-d '[' -f3 | cut -d ']' -f1 | uniq > afterlog.txt
cat 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 文本處理命令的強大能力。我在本文中是從命令行使用它們的， 不過您也可以在腳本中使用它們。
您應該記錄可能會遇到的盡可能多的內容，不過不要忘了保持性能。特別要 注意對遠程調用進行日志記錄，以及在線程分支、開始和結束的位置進行日志記 錄。日志中的信息越多，您所能實現數據挖掘就越強有力。
