最近一段时间比较辛苦,产品上线之后问题不断,最近更出现了多个阻塞问题,全靠分析进程栈文件的内容来辅助定位问题。平心而论,做Java开发比较省心,平时开发过程中可能不像在Linux下做C/C++开发的兄弟一样,经常需要分析程序栈和Core文件,而且Java开发过程中可用的调试工具非常多,功能强大,而且调试时也非常方便,但是,分析程序栈仍然是不可或缺的、重要的方法,尤其在产品上线之后,用户出于各种原因可能不乐意软件开发人员部署各种各样的工具,这时,分析程序栈就成了唯一可用并且好用的方法。
首先,Java应用程序的栈如何获取?JDK提供了非常多的工具来完成这个需求,比如GUI界面的jconsole、jvisualvm,命令行下的jstack。GUI的工具比较简单,这里主要讲jstack,比较基础,特别适合在服务器上使用。如下是jstack工具的使用帮助。
- jstack -l
- Usage:
- jstack [-l] <pid>
- (to connect to running process)
- jstack -F [-m] [-l] <pid>
- (to connect to a hung process)
- jstack [-m] [-l] <executable> <core>
- (to connect to a core file)
- jstack [-m] [-l] [server_id@]<remote server IP or hostname>
- (to connect to a remote debug server)
- Options:
- -F to force a thread dump. Use when jstack <pid> does not respond (process
- is hung)
- -m to print both java and native frames (mixed mode)
- -l long listing. Prints additional information about locks
- -h or -help to print this help message
-m,附加到运行状态的Java应用,可以同时导出java语言和本地栈的信息。
-F,对于-l和-m选项无法导出栈信息时,就只好使用-F选项,强制导出应用的栈信息;照我的理解,这是最后的选择。
jstack强大之处在于除了可以导出在本地运行的Java应用的栈信息,还可以导出运行于远程机器上的Java应用的栈信息,不过这个特性没有怎么用过,需要什么配置还不清楚,这里就不展开了。
下面对一段实例解析,比如对日常开发中常用到的Eclipse导出栈信息,如下。
- 2013-01-13 11:02:31
- Full thread dump Java HotSpot(TM) Client VM (23.1-b03 mixed mode, sharing):
- "[ThreadPool Manager] - Idle Thread" daemon prio=6 tid=0x069a3400 nid=0x84 in Object.wait() [0x0795f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x239102b8> (a org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor)
- at java.lang.Object.wait(Object.java:503)
- at org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor.run(Executor.java:106)
- - locked <0x239102b8> (a org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor)
- Locked ownable synchronizers:
- - None
- "Worker-2" prio=6 tid=0x032e5400 nid=0xfc in Object.wait() [0x0655f000]
- java.lang.Thread.State: TIMED_WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x27fd3118> (a org.eclipse.core.internal.jobs.WorkerPool)
- at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:185)
- - locked <0x27fd3118> (a org.eclipse.core.internal.jobs.WorkerPool)
- at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:217)
- at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)
- Locked ownable synchronizers:
- - None
- "Worker-1" prio=6 tid=0x052dd400 nid=0xd88 in Object.wait() [0x0645f000]
- java.lang.Thread.State: TIMED_WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x27fd3118> (a org.eclipse.core.internal.jobs.WorkerPool)
- at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:185)
- - locked <0x27fd3118> (a org.eclipse.core.internal.jobs.WorkerPool)
- at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:217)
- at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)
- Locked ownable synchronizers:
- - None
- "Bundle File Closer" daemon prio=6 tid=0x052d0800 nid=0xed8 in Object.wait() [0x04aef000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x294bc768> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
- at java.lang.Object.wait(Object.java:503)
- at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:397)
- - locked <0x294bc768> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
- at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:333)
- Locked ownable synchronizers:
- - None
- "Java indexing" daemon prio=4 tid=0x04ddd400 nid=0x1b0 in Object.wait() [0x05e5f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x289f02e8> (a org.eclipse.jdt.internal.core.search.indexing.IndexManager)
- at java.lang.Object.wait(Object.java:503)
- at org.eclipse.jdt.internal.core.search.processing.JobManager.run(JobManager.java:381)
- - locked <0x289f02e8> (a org.eclipse.jdt.internal.core.search.indexing.IndexManager)
- at java.lang.Thread.run(Unknown Source)
- Locked ownable synchronizers:
- - None
- "[Timer] - Main Queue Handler" daemon prio=6 tid=0x0398d800 nid=0x824 in Object.wait() [0x0416f000]
- java.lang.Thread.State: TIMED_WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x28105b68> (a java.lang.Object)
- at org.eclipse.equinox.internal.util.impl.tpt.timer.TimerImpl.run(TimerImpl.java:141)
- - locked <0x28105b68> (a java.lang.Object)
- at java.lang.Thread.run(Unknown Source)
- Locked ownable synchronizers:
- - None
- "Framework Event Dispatcher" daemon prio=6 tid=0x02c4c400 nid=0x56c in Object.wait() [0x03f6f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x27fd3140> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
- at java.lang.Object.wait(Object.java:503)
- at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:397)
- - locked <0x27fd3140> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
- at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:333)
- Locked ownable synchronizers:
- - None
- "Start Level Event Dispatcher" daemon prio=6 tid=0x03178400 nid=0xd50 in Object.wait() [0x03e6f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x27fd31b0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
- at java.lang.Object.wait(Object.java:503)
- at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:397)
- - locked <0x27fd31b0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
- at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:333)
- Locked ownable synchronizers:
- - None
- "State Data Manager" daemon prio=6 tid=0x02c4f400 nid=0x908 waiting on condition [0x03d6f000]
- java.lang.Thread.State: TIMED_WAITING (sleeping)
- at java.lang.Thread.sleep(Native Method)
- at org.eclipse.osgi.internal.baseadaptor.StateManager.run(StateManager.java:306)
- at java.lang.Thread.run(Unknown Source)
- Locked ownable synchronizers:
- - None
- "Service Thread" daemon prio=6 tid=0x02c45c00 nid=0x1ac runnable [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "C1 CompilerThread0" daemon prio=10 tid=0x02c43000 nid=0xd68 waiting on condition [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Attach Listener" daemon prio=10 tid=0x02c41800 nid=0xf64 waiting on condition [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Signal Dispatcher" daemon prio=10 tid=0x02c40000 nid=0x8ec runnable [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Finalizer" daemon prio=8 tid=0x02c25000 nid=0xeb0 in Object.wait() [0x030ef000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x27eaf9c8> (a java.lang.ref.ReferenceQueue$Lock)
- at java.lang.ref.ReferenceQueue.remove(Unknown Source)
- - locked <0x27eaf9c8> (a java.lang.ref.ReferenceQueue$Lock)
- at java.lang.ref.ReferenceQueue.remove(Unknown Source)
- at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)
- Locked ownable synchronizers:
- - None
- "Reference Handler" daemon prio=10 tid=0x02c20000 nid=0xe90 in Object.wait() [0x02fef000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x27eaf680> (a java.lang.ref.Reference$Lock)
- at java.lang.Object.wait(Object.java:503)
- at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
- - locked <0x27eaf680> (a java.lang.ref.Reference$Lock)
- Locked ownable synchronizers:
- - None
- "main" prio=6 tid=0x00ad8400 nid=0xe4c runnable [0x0012f000]
- java.lang.Thread.State: RUNNABLE
- at org.eclipse.swt.internal.win32.OS.WaitMessage(Native Method)
- at org.eclipse.swt.widgets.Display.sleep(Display.java:4311)
- at org.eclipse.ui.application.WorkbenchAdvisor.eventLoopIdle(WorkbenchAdvisor.java:364)
- at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2406)
- at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2369)
- at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2221)
- at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:500)
- at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
- at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:493)
- at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
- at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:113)
- at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:194)
- at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
- at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
- at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:368)
- at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
- at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
- at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
- at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
- at java.lang.reflect.Method.invoke(Unknown Source)
- at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:559)
- at org.eclipse.equinox.launcher.Main.basicRun(Main.java:514)
- at org.eclipse.equinox.launcher.Main.run(Main.java:1311)
- Locked ownable synchronizers:
- - None
- "VM Thread" prio=10 tid=0x02c1e800 nid=0x788 runnable
- "VM Periodic Task Thread" prio=10 tid=0x02c53800 nid=0xfbc waiting on condition
- JNI global references: 272
- "[ThreadPool Manager] - Idle Thread" daemon prio=6 tid=0x069a3400 nid=0x84 in Object.wait() [0x0795f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x239102b8> (a org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor)
- at java.lang.Object.wait(Object.java:503)
- at org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor.run(Executor.java:106)
- - locked <0x239102b8> (a org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor)
- Locked ownable synchronizers:
- - None
1、这个线程的名称为[ThreadPool Manager] - Idle Thread,实际开发过程中使用可以使用Thread对象的setName方法修改;这里可以看出设置线程名字属性的必要性,导出栈信息的时候就有用了,可以通过线程名字方便的定位到问题代码块;
2、优先级为6,不过优先级意义不大,对分析应用帮助不大,Java的教程中也不推荐修改线程的优先级,所以这里跳过;
3、tid和nid,16进制表示,这两个字段中有一个可以对应到操作系统调度时使用的线程ID,这在Linux下特别有用,因为top -H命令可以输出各个线程的CPU占用率,借助栈信息,可以方便的定位到CPU占用高的线程,这个很有用,在其它平台暂时还看不出什么意义;
4、当前栈顶,为java.lang.Object.wait方法;
5、线程状态,java.lang.Thread.State: WAITING (on object monitor);java.lang.Thread.State是什么?有兴趣的话可以翻看JDK的源码,源码很简单,注释很详细,给出了Java线程可能存在的状态;
6、当前线程是否处于同步块内, Locked ownable synchronizers:,这里值为None,说明当前线程没有处于同步块内。
限于我自己对于Java栈的理解,这里对于单个线程栈的解读比较粗,不过说来应当是够用了。
上面写了Java程序栈的获取方法和格式,那么有一个问题,为什么要获取栈信息、解析这个栈信息有什么用呢?这是一个好问题,毕竟无利不起早,程序员是世界上最聪明的人类群体,没有时间花费在没有产出的事情。虽然做Java开发相比较C/C++要容易一些,但在分析死锁、CPU高的问题时,分析的手法和C/C++程序员差不多,基本都要通过栈调用来分析问题。
通过栈信息分析CPU高的方法上面已经讲过,这里简单说明一下,借助Linux下的top -H命令,输出全部线程的CPU、内存信息,找到占用比较高的线程ID,换算成16进制,然后在栈信息文件中搜索,检查是否有匹配行,如果找到并且位置在nid=或者tid=的后面,说明事发线程找到了。
通过栈信息分析死锁问题的方法相对要麻烦一点,需要一点准备知识,对Java语言的线程可能处于的状态有一定了解,Java语言教程里的讲解比较抽象,这里先来点干货,直接上点JDK中的源码。引用JDK的源码希望不会招致JDK开发人员的不满,这里仅仅是为了叙述方便。
- public enum State {
- /**
- * Thread state for a thread which has not yet started.
- */
- NEW,
- /**
- * Thread state for a runnable thread. A thread in the runnable
- * state is executing in the Java virtual machine but it may
- * be waiting for other resources from the operating system
- * such as processor.
- */
- RUNNABLE,
- /**
- * Thread state for a thread blocked waiting for a monitor lock.
- * A thread in the blocked state is waiting for a monitor lock
- * to enter a synchronized block/method or
- * reenter a synchronized block/method after calling
- * {@link Object#wait() Object.wait}.
- */
- BLOCKED,
- /**
- * Thread state for a waiting thread.
- * A thread is in the waiting state due to calling one of the
- * following methods:
- * <ul>
- * <li>{@link Object#wait() Object.wait} with no timeout</li>
- * <li>{@link #join() Thread.join} with no timeout</li>
- * <li>{@link LockSupport#park() LockSupport.park}</li>
- * </ul>
- *
- * <p>A thread in the waiting state is waiting for another thread to
- * perform a particular action.
- *
- * For example, a thread that has called <tt>Object.wait()</tt>
- * on an object is waiting for another thread to call
- * <tt>Object.notify()</tt> or <tt>Object.notifyAll()</tt> on
- * that object. A thread that has called <tt>Thread.join()</tt>
- * is waiting for a specified thread to terminate.
- */
- WAITING,
- /**
- * Thread state for a waiting thread with a specified waiting time.
- * A thread is in the timed waiting state due to calling one of
- * the following methods with a specified positive waiting time:
- * <ul>
- * <li>{@link #sleep Thread.sleep}</li>
- * <li>{@link Object#wait(long) Object.wait} with timeout</li>
- * <li>{@link #join(long) Thread.join} with timeout</li>
- * <li>{@link LockSupport#parkNanos LockSupport.parkNanos}</li>
- * <li>{@link LockSupport#parkUntil LockSupport.parkUntil}</li>
- * </ul>
- */
- TIMED_WAITING,
- /**
- * Thread state for a terminated thread.
- * The thread has completed execution.
- */
- TERMINATED;
- }
1、什么状态下是NEW,线程对象被new出来,但是还没有调用start方法,这时就被称为NEW;
2、RUNNABLE,线程对象已经被调用了start方法,但是,这个线程的run方法可能运行也可能没有运行,依赖于操作系统的行为;
3、BLOCKED,简单的说,线程进入了synchronized关键字标识的同步块,但和4状态有所区别;
4、WAITING和TIMED_WAITING差不多,一般是调用了对象的wait方法,需要其它线程在特定场景使用notify/notifyAll方法;
5、TERMINATED,这个状态比较直白,run方法退出运行,即进入这个状态;
今天先写到这里,有时间再举几个例子说明一下怎么基于上述信息从栈信息中分析出死锁的线程
栈信息本身并不神秘,格式和内容都比较单一,但借助程序的调用栈信息可以观察到很多有用的信息。借助栈信息来分析有时候被认为是一种秘技,实际上这是一种误解。古人云,读书百遍,其义自见,程序调用栈信息看多了自然就会明白。下面结合java.lang.Thread.State类的注释,举几个代码及其调用栈的例子,相信对于聪明的同学,入门就不困难了。但原理什么的,就得靠自己了,至少得读一下java.lang.Thread.State类的注释吧。
下面的例子都是使用Oracle公司出品的Java7编译和测试的,具体的版本信息如下。
- java -version
- java version "1.7.0_11"
- Java(TM) SE Runtime Environment (build 1.7.0_11-b21)
- Java HotSpot(TM) Client VM (build 23.6-b04, mixed mode, sharing)
例子一
- public class DeadLock {
- public static void main(final String[] args) throws Exception {
- final Object obj = new Object();
- new Thread() {
- @Override
- public void run() {
- callWait(obj);
- };
- }.start();
- Thread.sleep(3000L);
- synchronized (obj) {
- try {
- obj.wait();
- }
- catch (final InterruptedException e) {
- e.printStackTrace();
- }
- }
- }
- static void callWait(final Object obj) {
- synchronized (obj) {
- try {
- obj.wait();
- }
- catch (final InterruptedException e) {
- e.printStackTrace();
- }
- }
- }
- }
- "main" prio=6 tid=0x00868800 nid=0x1370 in Object.wait() [0x0098f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x22bc2c08> (a java.lang.Object)
- at java.lang.Object.wait(Object.java:503)
- at DeadLock.main(DeadLock.java:30)
- - locked <0x22bc2c08> (a java.lang.Object)
- Locked ownable synchronizers:
- - None
- "Thread-0" prio=6 tid=0x02b22000 nid=0x1044 in Object.wait() [0x0316f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x22bc2c08> (a java.lang.Object)
- at java.lang.Object.wait(Object.java:503)
- at DeadLock$1.run(DeadLock.java:14)
- - locked <0x22bc2c08> (a java.lang.Object)
- Locked ownable synchronizers:
- - None
例子二
- public class DeadLock {
- public static void main(final String[] args) throws Exception {
- Thread.currentThread().setName("main thread");
- final Thread r = new Thread() {
- @Override
- public void run() {
- try {
- Thread.sleep(200000L);
- }
- catch (final InterruptedException e) {
- e.printStackTrace();
- }
- };
- };
- r.setName("another thread");
- r.start();
- System.out.println("start to sleeping");
- Thread.sleep(100000L);
- System.out.println("start to joining");
- r.join();
- }
- }
- "another thread" prio=6 tid=0x02b22400 nid=0x2058 waiting on condition [0x0316f000]
- java.lang.Thread.State: TIMED_WAITING (sleeping)
- at java.lang.Thread.sleep(Native Method)
- at DeadLock$1.run(DeadLock.java:9)
- Locked ownable synchronizers:
- - None
- "main thread" prio=6 tid=0x00868800 nid=0x2720 waiting on condition [0x0098f000]
- java.lang.Thread.State: TIMED_WAITING (sleeping)
- at java.lang.Thread.sleep(Native Method)
- at DeadLock.main(DeadLock.java:19)
- Locked ownable synchronizers:
- - None
- "another thread" prio=6 tid=0x02b22400 nid=0x2058 waiting on condition [0x0316f000]
- java.lang.Thread.State: TIMED_WAITING (sleeping)
- at java.lang.Thread.sleep(Native Method)
- at DeadLock$1.run(DeadLock.java:9)
- Locked ownable synchronizers:
- - None
- "main thread" prio=6 tid=0x00868800 nid=0x2720 in Object.wait() [0x0098f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x22bc3d70> (a DeadLock$1)
- at java.lang.Thread.join(Thread.java:1258)
- - locked <0x22bc3d70> (a DeadLock$1)
- at java.lang.Thread.join(Thread.java:1332)
- at DeadLock.main(DeadLock.java:21)
- Locked ownable synchronizers:
- - None
例子三
- public class DeadLock {
- public static void main(final String[] args) throws Exception {
- final Object lock1 = new Object();
- final Object lock2 = new Object();
- Thread.currentThread().setName("main-thread");
- final Thread r = new Thread("another-thread") {
- @Override
- public void run() {
- try {
- synchronized (lock2) {
- Thread.sleep(20000);
- synchronized (lock1) {
- Thread.sleep(20000);
- }
- }
- }
- catch (final Exception e) {
- e.printStackTrace();
- }
- }
- };
- r.start();
- Thread.sleep(5000);
- synchronized (lock1) {
- Thread.sleep(20000);
- synchronized (lock2) {
- Thread.sleep(20000);
- }
- }
- }
- }
- "another-thread" prio=6 tid=0x02b22400 nid=0x2250 waiting for monitor entry [0x0316f000]
- java.lang.Thread.State: BLOCKED (on object monitor)
- at DeadLock$1.run(DeadLock.java:14)
- - waiting to lock <0x22bc3f90> (a java.lang.Object)
- - locked <0x22bc3f98> (a java.lang.Object)
- Locked ownable synchronizers:
- - None
- "main-thread" prio=6 tid=0x00868800 nid=0x2634 waiting for monitor entry [0x0098f000]
- java.lang.Thread.State: BLOCKED (on object monitor)
- at DeadLock.main(DeadLock.java:28)
- - waiting to lock <0x22bc3f98> (a java.lang.Object)
- - locked <0x22bc3f90> (a java.lang.Object)
- Locked ownable synchronizers:
- - None
- Found one Java-level deadlock:
- =============================
- "another-thread":
- waiting to lock monitor 0x02ad433c (object 0x22bc3f90, a java.lang.Object),
- which is held by "main-thread"
- "main-thread":
- waiting to lock monitor 0x02ad363c (object 0x22bc3f98, a java.lang.Object),
- which is held by "another-thread"
- Java stack information for the threads listed above:
- ===================================================
- "another-thread":
- at DeadLock$1.run(DeadLock.java:14)
- - waiting to lock <0x22bc3f90> (a java.lang.Object)
- - locked <0x22bc3f98> (a java.lang.Object)
- "main-thread":
- at DeadLock.main(DeadLock.java:28)
- - waiting to lock <0x22bc3f98> (a java.lang.Object)
- - locked <0x22bc3f90> (a java.lang.Object)
- Found 1 deadlock.
主线程中提示了当前持有的锁和期望获取的锁,而新线程也存在类似的提示,只是获取锁的顺序不同。从栈信息可以看出,两个线程都处于BLOCKED状态。可能是源代码中的问题过于明显,导出的栈信息中给出了死锁的提示信息,实际项目的业务代码比样例要复杂,JVM可能做不到这么智能。这里的提示信息多多少少有点让我失望,在主线程栈信息的最后一部分没有输出当前持有锁的列表,很奇怪,不知道是不是和JDK的实现有关。
样例四
- import java.security.SecureRandom;
- import java.util.concurrent.SynchronousQueue;
- import java.util.concurrent.ThreadFactory;
- import java.util.concurrent.ThreadPoolExecutor;
- import java.util.concurrent.TimeUnit;
- import java.util.concurrent.atomic.AtomicInteger;
- import java.util.concurrent.locks.ReentrantLock;
- public class DeadLock {
- private final ReentrantLock lock = new ReentrantLock();
- private static final SecureRandom random = new SecureRandom();
- public DeadLock() {
- }
- public void runWork() {
- final ThreadPoolExecutor threadpool = new ThreadPoolExecutor(3, 3, 60L, TimeUnit.DAYS,
- new SynchronousQueue<Runnable>(), new ThreadFactory() {
- private final AtomicInteger counter = new AtomicInteger(1);
- @Override
- public Thread newThread(final Runnable r) {
- return new Thread(r, "thread-sn-" + counter.getAndIncrement());
- }
- });
- threadpool.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
- Thread.currentThread().setName("main-thread");
- for (int i = 0; i < 15; ++i) {
- threadpool.submit(new Runnable() {
- @Override
- public void run() {
- try {
- int timeout = 0;
- while ((timeout = random.nextInt()) <= 0) {
- }
- timeout = timeout % 111;
- Thread.sleep(timeout * 100L);
- lock.lock();
- callLongTime();
- }
- catch (final Exception e) {
- e.printStackTrace();
- }
- finally {
- lock.unlock();
- }
- }
- });
- }
- threadpool.shutdown();
- }
- public static void main(final String[] args) throws Exception {
- new DeadLock().runWork();
- }
- static long callLongTime() {
- System.out.println("thread name " + Thread.currentThread().getName());
- long sum = 0;
- for (long i = 0; i < 10000000000L; ++i) {
- sum = sum ^ i + i;
- }
- return sum;
- }
- }
- "thread-sn-3" prio=6 tid=0x02de8400 nid=0x2688 runnable [0x0320f000]
- java.lang.Thread.State: RUNNABLE
- at DeadLock.callLongTime(DeadLock.java:63)
- at DeadLock$2.run(DeadLock.java:41)
- at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
- at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
- at java.util.concurrent.FutureTask.run(FutureTask.java:166)
- at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
- at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
- at java.lang.Thread.run(Thread.java:722)
- Locked ownable synchronizers:
- - <0x22be1488> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- - <0x22be66d8> (a java.util.concurrent.ThreadPoolExecutor$Worker)
- "thread-sn-2" prio=6 tid=0x02de6c00 nid=0x218c waiting on condition [0x031bf000]
- java.lang.Thread.State: WAITING (parking)
- at sun.misc.Unsafe.park(Native Method)
- - parking to wait for <0x22be1488> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
- at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
- at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
- at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
- at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214)
- at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
- at DeadLock$2.run(DeadLock.java:40)
- at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
- at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
- at java.util.concurrent.FutureTask.run(FutureTask.java:166)
- at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
- at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
- at java.lang.Thread.run(Thread.java:722)
- Locked ownable synchronizers:
- - <0x22be64e0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
写在后面
简单的几个样例而已,不必纠结。重点是栈信息是有用的,栈信息并不复杂,但是需要一定的耐心。
家里有了宝宝,白天的时间都要抱小孩,码字的时间就少了,只好等晚上宝宝睡了,才有机会写写。
关于Java应用导出的栈信息,由于包含了线程ID,因而还有一个妙用,即可以用来分析各个线程CPU占用情况,这样可以用来分析CPU占用过高的问题,从而指导CPU相关的优化类工作。
先看导出的栈信息的一部分。
- "main" prio=6 tid=0x00868c00 nid=0x19a4 waiting on condition [0x0098f000]
- java.lang.Thread.State: TIMED_WAITING (sleeping)
- at java.lang.Thread.sleep(Native Method)
- at DeadLock.main(DeadLock.java:3)
- Locked ownable synchronizers:
- - None
对于Linux平台,可以使用top命令和选项H,样例如下。
- # top -H -p <pid>
对于Windows平台,需要下载一个免费的工具,鼎鼎大名的ProcessExplorer。通过这个工具,可以方便的查看目标Java进程的线程ID列表及CPU占用率,但为了查明占用CPU高的线程具体在做什么,还是需要将线程ID手工转换为16进制表示,然后到栈信息文件中查找。
如果亲自动手分析Java应用导出的栈信息的话,可以惊讶的发现,原来栈信息中包括了JVM完成自己特定任务的线程栈信息。下面看个例子。
- public class Test {
- public static void main(final String[] args) throws Exception {
- Thread.sleep(200000L);
- }
- }
- -XX:+UseConcMarkSweepGC
- 2013-02-12 01:27:24
- Full thread dump Java HotSpot(TM) Client VM (23.6-b04 mixed mode):
- "Service Thread" daemon prio=6 tid=0x17975c00 nid=0x202c runnable [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "C1 CompilerThread0" daemon prio=10 tid=0x17973400 nid=0x25dc waiting on condition [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Attach Listener" daemon prio=10 tid=0x1796e400 nid=0x1cf0 waiting on condition [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Signal Dispatcher" daemon prio=10 tid=0x1796cc00 nid=0x1d3c runnable [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Surrogate Locker Thread (Concurrent GC)" daemon prio=6 tid=0x1796b400 nid=0x21ec waiting on condition [0x00000000]
- java.lang.Thread.State: RUNNABLE
- Locked ownable synchronizers:
- - None
- "Finalizer" daemon prio=8 tid=0x17921800 nid=0x2618 in Object.wait() [0x177df000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x02be56a0> (a java.lang.ref.ReferenceQueue$Lock)
- at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- - locked <0x02be56a0> (a java.lang.ref.ReferenceQueue$Lock)
- at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
- at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)
- Locked ownable synchronizers:
- - None
- "Reference Handler" daemon prio=10 tid=0x02b3e400 nid=0x2304 in Object.wait() [0x1778f000]
- java.lang.Thread.State: WAITING (on object monitor)
- at java.lang.Object.wait(Native Method)
- - waiting on <0x02be5278> (a java.lang.ref.Reference$Lock)
- at java.lang.Object.wait(Object.java:503)
- at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- - locked <0x02be5278> (a java.lang.ref.Reference$Lock)
- Locked ownable synchronizers:
- - None
- "main" prio=6 tid=0x00868c00 nid=0x1dc waiting on condition [0x0098f000]
- java.lang.Thread.State: TIMED_WAITING (sleeping)
- at java.lang.Thread.sleep(Native Method)
- at DeadLock.main(DeadLock.java:3)
- Locked ownable synchronizers:
- - None
- "VM Thread" prio=10 tid=0x02b38800 nid=0x195c runnable
- "Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x0086c800 nid=0x2780 runnable
- "Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x02a40c00 nid=0x25a0 runnable
- "Concurrent Mark-Sweep GC Thread" prio=10 tid=0x02ab6000 nid=0x1828 runnable
- "VM Periodic Task Thread" prio=10 tid=0x17989c00 nid=0x20b0 waiting on condition
- JNI global references: 115
这里举这个例子只是想说明通过分析Java应用导出的栈信息文件是一种很有效的窥视JVM内部实现的方法,至于能窥视到多少信息,就要看各人的实力了。本人才疏学浅,暂时还看不出什么特别的东东,目前只能看出JVM自动生成了哪些线程,至于各个线程的作用,除了垃圾回收器相关的,其它线程的功能暂时还不清楚,留待以后找到资料再说。
曾经在工作中借助top之类的命令来定位Java应用占用CPU过高的问题时,偶然发现过执行垃圾回收任务的线程占用很高CPU的情况,不过问题的根本原因和JVM倒没有什么关系