1. 導言
程序的性能分析是應用程序開發過程中的一個重要方面。這個工作一般是由一些專業人員來完成的，他們的目標是在一個特定的平台上，提高代碼的性能。當程序是運行在多核平台的多線程或者並行程序的時候，提高性能這個問題就變得更加困難了。因為在這樣的情況下，不僅需要考慮代碼的性能，還需要考慮代碼的可伸縮性。
隨著Java 5中引入了java.util.concurrent (JUC)包，在Java語言中出現了一種新的鎖。JUC包使用得越來越普遍，因為更多的應用程序需要為了多核系統而開發或仔細地調優。雖然JLM可以找到傳統的Java鎖的詳細的競爭信息，但是卻沒有同樣的工具能夠找到java.util.concurrent.locks包的鎖競爭信息。 Sun/Oracle、IBM，還有其他Java廠商也都沒有這樣的工具。缺乏對JUC鎖的剖析工具正是我們開發這個鎖工具，jucprofiler（Multicore SDK的一部分）的動機。
2. jucprofiler概覽
當在程序中使用JUC鎖的時候，線程會在下面兩種情況下“停止”執行：
當線程A試圖去獲得一個JUC鎖，但這個鎖卻已經被另外一個線程獲得，那麼線程A不得不“停止”，直到這個鎖被釋放或者超時。
當線程A調用了java.util.concurrent.locks.Condition的任意一個“等待”的API，線程A會停止執行，直到另外一個線程通知它或者超時。
我們分別把這兩種情況稱作“鎖競爭時間”和“等待時間”。
jucprofiler就是為了捕獲以上兩種情況的時間開銷而設計和實現的。
2.1. 代碼修改（Instruments）
為了獲取JUC鎖的運行時數據，需要提前修改一些JUC類，然後替換掉JRE中相應的類。在首次使用jucprofiler之前，用戶需要運行命令去生成PreInstrument.jar。假設JRE沒有改變的話，這個步驟只需要做一次。（如果用戶改變了JRE，那麼用戶需要自己刪除 PreInstrument.jar，然後重新運行這個命令，來再次生成PreInstrument.jar）。
2.1.1. 鎖競爭時間開銷
對於鎖競爭時間開銷，jucprofiler記錄了申請類 java.util.concurrent.locks.AbstractQueuedSynchronizer 和類java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject的實例，並且給這些實例分配唯一的標識。
類 方法 調用位置 java.util.concurrent.locks.LockSupport park (Object); 類AbstractQueuedSynchronizer中的方法parkAndCheckInterrupt() parkNanos(Object blocker, long nanos) 類AbstractQueuedSynchronizer中的方法doAcquireNanos(int arg, long nanosTimeout)與doAcquireSharedNanos(int arg, long nanosTimeout)
2.1.2. 鎖等待時間開銷
對於鎖等待時間開銷，jucprofiler獲取了在不同的位置調用類java.util.concurrent.locks.LockSupport的方法park(blocker)與parkNanos(blocker, nanos)的時間開銷：
類 方法 調用位置 java.util.concurrent.locks.LockSupport park (Object); 類 AbstractQueuedSynchronizer除parkAndCheckInterrupt()以外的方法 parkNanos(Object blocker, long nanos) 類AbstractQueuedSynchronizer除doAcquireNanos(int arg, long nanosTimeout)與doAcquireSharedNanos(int arg, long nanosTimeout) 以外的方法
3. 如何使用
本節將通過一個真實的應用來探究如何使用jucprofiler來尋找程序中的問題。
3.1. 運行jucprofiler
使用如下的命令：
$ java -Xbootclasspath/p:$JUCP/BCIRuntime.jar:$JUCP/PreInstrument.jar
-javaagent:$JUCP/BCIAgent.jar=callStackDepth=10:allocationStackDepth=0
:,msdk.idp=com.ibm.msdk.bciagent.JUCInstrumentDecisionProvider,:libPath=$JUCP:traceJUC=on
-cp .:derby.jar JavaDBDemo
jucprofiler可以用於任何運行在JDK6上的Java程序上。假設jucprofiler安裝在了目錄$JUCP中，在 jucprofiler運行完你的程序之後，就會生成一個叫"BCIAgent.***.bci.trace"的文件，其中"***"代表本次運行的唯一時間戳。
3.2. 獲取結果
運行如下所示的命令來得到結果：
$ java -Xmx1000m -jar $JUCP/BCITraceReader.jar {tracefile} {resultOutputFile}
其中：
{tracefile}是一個追蹤文件的全路徑名稱或者是一個包含若干追蹤文件的目錄名稱，比如BCIAgent.***.bci.trace。
{resultOutputFile}是可選的參數，用來指定存放分析結果的文件。如果沒有這個選現，那麼分析結果就會在控制台打印出來。
說明：因為對追蹤文件事後分析過程會有一些內存開銷，所以最好用Java選項-Xmx來增加堆的大小。在我們的實驗裡，分析160M的文件，需要800M的內存。
3.3. 結果解析
如下圖所示，純文本輸出包含了不同類型的信息，比如鎖的名稱，鎖競爭的次數和時間，鎖被持有的時間和次數，鎖在申請時線程的調用棧，持續的時間和每一次鎖競爭的調用棧。這些結果有助於用戶發現JUC鎖競爭造成的程序瓶頸。
在“LEGEND” 段之前，結果報告首先，按照鎖競爭次數和時間的降序，總結了程序中全部的JUC鎖競爭。其中每一行屬於兩種類型的一種，“AQS”代表JUC 鎖，“CHM”代表ConcurrentHashMap. 因為一個ConcurrentHashMap內部被分割為了若干個片段（segment）進行存儲，而且每一個片段都被一個不同的JUC鎖保護，所以，從鎖的角度來看，ConcurrentHashMap可以被看作為一個JUC鎖的集合。例如，“CHM@8”有276次鎖競爭，一共3,945,7000 納秒的競爭時間，這就是說，“CHM@8”中的所有片段的JUC鎖共有276次鎖競爭，一共3,945,7000納秒的競爭時間。這樣的對鎖的分組能夠幫助程序員發現哪一個ConcurrentHashMap對象發生了最嚴重的鎖競爭。相反，JUC鎖“AQS@1790” 不屬於任何一個ConcurrentHashMap對象，它就是程序中一個顯式使用的鎖。
說明：因為在這個例子中，沒有打開記錄獲得鎖的功能，所以列HOLD-COUNT和HOLD-TIME都是零。
在“LEGEND”段之後，結果給出了每一個JUC鎖競爭的詳細信息。在下邊的結果片段中，對於ConcurrentHashMap “CHM@8” ，鎖競爭出現在兩個用來保護片段的鎖上 “Lock [AQS@135]” and “Lock [AQS@146]”。對於“Lock [AQS@135]”，它在一個程序位置出現競爭，顯示了競爭的次數，時間和競爭時刻的線程調用棧。對於“Lock [AQS@146]”，給出了同樣的信息。這些細節信息可以很好地幫助程序員來定位程序中的鎖競爭，並且清楚地理解ConcurrentHashMap中哪個片段競爭最嚴重。
Multicore Software Development Toolkit Version_2.1
j.u.c Lock Profiler Report
NAME CONTD-COUNT CONTD-TIME HOLD-COUNT HOLD-TIME
CHM@8 276 39457000 0 0
AQS@1790 36 4029000 0 0
AQS@131 17 630000 0 0
=================================================================================================
LEGEND:
NAME : Name of juc lock(AQS) or ConcurrentHashMap(CHM), format: <Type>@<Idgt;
CONTD-COUNT : Total count of lock contention
CONTD-TIME : Total time of lock contention in nanosecond
HOLD-COUNT : Total count of lock hold
HOLD-TIME : Total time of lock hold in nanosecond
==================================================================================================
ConcurrentHashMap [CHM@8]:
-----------------------------------------------------------------------------------------------------------
Lock [AQS@135]:
-----------------------------------------------------------------------------------------------------------
Lock Contention 1
CONTD-COUNT: 25
CONTD-TIME: 10827000
Call Stack:
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:758)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:789)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1125)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:197)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:273)
java.util.concurrent.ConcurrentHashMap$Segment.remove(ConcurrentHashMap.java:530)
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:934)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlock(ConcurrentLockSet.java:740)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlockReference(ConcurrentLockSet.java:784)
org.apache.derby.impl.services.locks.LockSpace.unlockReference(LockSpace.java:275)
Lock [AQS@146]:
-----------------------------------------------------------------------------------------------------------
Lock Contention 1
CONTD-COUNT: 22
CONTD-TIME: 2009000
Call Stack:
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:758)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:789)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1125)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:197)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:273)
java.util.concurrent.ConcurrentHashMap$Segment.remove(ConcurrentHashMap.java:530)
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:934)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlock(ConcurrentLockSet.java:740)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlockReference(ConcurrentLockSet.java:784)
org.apache.derby.impl.services.locks.LockSpace.unlockReference(LockSpace.java:275)
3.4. 在可視化分析器中打開追蹤文件
可視化分析器，作為multicore SDK的一部分，提供了一些Eclipse視圖，可以用表格和圖表來顯示jucprofiler文件。當前有兩個視圖，一個叫“J.U.C 統計”視圖，另外一個叫“J.U.C 同步”視圖。
“J.U.C 統計”視圖如下所示。右邊的兩列是“競爭時間”和“競爭次數”。“申請棧”是關於JUC鎖在申請的時候的調用位置。
“J.U.C 同步”視圖如下所示。第一列是時間，表明什麼時候鎖出現了競爭。第二列是線程，表明鎖競爭發生哪個線程。第三列是鎖，表明那個JUC鎖出現競爭了。最後一列是方法，表明鎖競爭是在什麼位置發生的。
3.5. 在線控制
在執行的過程中，jucprofiler會創建一個“控制服務器”監聽2009端口。用戶可以使用“控制客戶端”連接這個端口，控制jucprofiler的行為，比如，可以動態打開或者關閉追蹤功能：
$ java -cp BCIRuntime.jar
com.ibm.msdk.bciruntime.control.ControlClient HOST -m [b|i] –b
START -e END
其中：
HOST：“控制客戶端”要去連接的主機名稱，缺省是本機。
-m [b|i]: “控制客戶端”執行的模式。- b是批處理模式、- i是交互模式。缺省是交互模式。
-b START：如果是批處理模式，START是開始剖析的時間。
-e END：END是剖析過程的持續時間。
3.5.1. 交互模式
有一個簡單的shell，用戶可以輸入一些命令juc.on和juc.off來打開和關閉jucprofiler。比如，java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient, “控制客戶端” 會連接到本機, 並且打開一個shell來控制jucprofiler.
$ java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient
jucprofiler control> juc.on
juc.on
jucprofiler t control> start
start
jucprofiler control> stop
stop
jucprofiler control> juc.off
juc.off
jmit control> quit
quit
$ java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient localhost -m b -b 2 -e 10
Start tracing in 2 seconds
Start tracing
Stop tracing in 10 seconds
Stop tracing
quit
3.5.2. 批處理模式
jucprofiler也支持批處理模式。比如， java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient mtrat-test.dyndns.org -m b -b 10 -e 10, 意思是 “控制客戶端”會連接到機器mtrat-test.dyndns.org，10秒後啟動jucprofiler，然後10秒後停止 jucprofiler。
4. 結論
隨著多核處理器成為主流，更多的並行/多線程Java程序將不斷湧現。我們需要更好的工具去剖析這些並行程序。本文介紹的jucprofiler填補了Java性能分析工具中的一個重要缺口。
