剖析java.util.concurrent锁

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锁的时候，线程会在下面两种情况下“停止”执行：

1. 当线程A试图去获得一个JUC锁，但这个锁却已经被另外一个线程获得，那么线程A不得不“停止”，直到这个锁被释放或者超时。
2. 当线程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} 

其中：

1. {tracefile}是一个追踪文件的全路径名称或者是一个包含若干追踪文件的目录名称，比如BCIAgent.***.bci.trace。
2. {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.1j.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 1CONTD-COUNT: 25CONTD-TIME: 10827000Call 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 1CONTD-COUNT: 22CONTD-TIME: 2009000Call 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.ControlClientjucprofiler control> juc.onjuc.onjucprofiler t control> startstartjucprofiler control> stopstopjucprofiler control> juc.offjuc.offjmit control> quitquit

$ java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient localhost -m b -b 2 -e 10Start tracing in 2 secondsStart tracingStop tracing in 10 secondsStop tracingquit

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性能分析工具中的一个重要缺口。

关于作者

齐尧是IBM中国开发中心新技术中心的工程师。他于2006年加入IBM。齐先生在Java虚拟机，字节码修改和Java编程方面都很有经验。他现在从事的项目是Java的运行时分析工具。齐先生在北京理工大学获得了计算机科学的硕士学位。

Raja Das是IBM软件部的软件架构师。他现在为多核系统开发库和框架。之前，他是 WebSphere?? Partner Gateway的产品架构师。Das先生的兴趣包括编程语言，并行软件和系统。

罗志达是IBM中国开发中心新技术中心的工程师。他于2008年加入IBM，在嵌入式软件开发上很有经验，现在的项目是运行时分析工具。罗先生在北京大学获得软件工程硕士学位。