剖析 java.util.concurrent 锁

来自 IBM 的工程师齐尧，Raja Das 和罗志达在本文中介绍了 jucprofiler，这个 alphaWorks 上的工具用于剖析使用了 java.util.concurrent 类的多 核平台上的应用程序，而 java.util.concurrent 类则是在 Java 5 中引入的。

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

关于作者

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

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

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

查看英文原文： Profiling java.util.concurrent locks

感谢张龙对本文的审校。

给InfoQ 中文站投稿或者参与内容翻译工作，请邮件至 editors@cn.infoq.com 。也欢迎大家加入到 InfoQ 中文站用户讨论组中与我们的编辑和其他读者朋友交流。