Java程序栈信息文件中的秘密(一)

转载 2015年11月20日 17:10:41

最近一段时间比较辛苦,产品上线之后问题不断,最近更出现了多个阻塞问题,全靠分析进程栈文件的内容来辅助定位问题。平心而论,做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

-l,一般用于附加到运行状态的Java应用,除导出栈信息外,还会记录各个线程当前持有或者等待的锁信息。

-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

Eclipse是用Java开发的,所以导出的栈信息从格式上应当是具有普适性的。从上述样例中,首先可以看出这段栈信息是在2013-01-13 11:02:31导出的,时间精确到了秒;另外还给出了Eclipse运行时使用的JRE的版本和类型。JRE分为桌面版和服务器版,Client标识当前应用使用了桌面版JRE,针对桌面应用进行了特别的优化,其它方面的区别可以Google一下,差别比较大,这里不赘述。java应用启动时,可以通过命令行选项控制对字节码的执行方式为纯解释、解释加编译(混合,mixed
mode)、纯编译,样例中使用了混合模式,JRE在运行时会对热点代码进行重点优化,翻译成机器代码运行,至于何为热点,可以继续Google,JVM有一套复杂的算法来甄别。

"[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程序栈信息文件中的秘密(一)

最近一段时间比较辛苦,产品上线之后问题不断,最近更出现了多个阻塞问题,全靠分析进程栈文件的内容来辅助定位问题。平心而论,做Java开发比较省心,平时开发过程中可能不像在Linux下做C/C++开发的兄...
  • guomei
  • guomei
  • 2013年12月17日 23:24
  • 610

Java程序栈信息文件中的秘密(二)

栈信息本身并不神秘,格式和内容都比较单一,但借助程序的调用栈信息可以观察到很多有用的信息。借助栈信息来分析有时候被认为是一种秘技,实际上这是一种误解。古人云,读书百遍,其义自见,程序调用栈信息看多了自...
  • babyblue_963
  • babyblue_963
  • 2013年02月11日 02:01
  • 3226

Java程序栈信息文件中的秘密(一)

最近一段时间比较辛苦,产品上线之后问题不断,最近更出现了多个阻塞问题,全靠分析进程栈文件的内容来辅助定位问题。平心而论,做Java开发比较省心,平时开发过程中可能不像在Linux下做C/C++开发的兄...
  • babyblue_963
  • babyblue_963
  • 2013年02月03日 22:50
  • 2648

Java程序栈信息文件中的秘密(四)

如果亲自动手分析Java应用导出的栈信息的话,可以惊讶的发现,原来栈信息中包括了JVM完成自己特定任务的线程栈信息。下面看个例子。 public class Test { public st...
  • babyblue_963
  • babyblue_963
  • 2013年02月12日 01:36
  • 2474

16.11.12acm第二次培训 Problem D: 字符串的加密

Description Chip和Dale发明了一种文本信息加密技术。他们事先秘密约定好矩阵的行数和列数。接着,将字符按如下方式编码: 1. 所有文本只包含大写字母和空格。 2. 每个字符均赋予一个...
  • zhengyuan233
  • zhengyuan233
  • 2016年11月14日 17:04
  • 537

Java:将异常的完整堆栈追踪信息保存到字符串中(详解)

​在Java开发中,我们经常要处理各种异常,我们一般用e.toString()或e.getMessage()得到异常信息,但是有时候异常堆栈中会存在很多信息,比如用下面的代码抛出异常: tr...
  • u010475284
  • u010475284
  • 2014年04月17日 17:20
  • 3530

如何在进程崩溃后打印堆栈并防止数据丢失

进程在运行过程中遇到逻辑错误, 比如除零, 空指针等等, 系统会触发一个软件中断.  这个中断会以信号的方式通知进程, 这些信号的默认处理方式是结束进程.  发生这种情况, 我们就认为进程崩溃了. ...
  • chengangdzzd
  • chengangdzzd
  • 2016年04月25日 17:31
  • 2574

jvm内存分析 计数器 堆 栈 本地方法栈 方法区

jvm 堆 : 与程序计数器一样,Java虚拟机栈(Java Virtual Machine Stacks)也是线程私有的,它的 生命周期与线程相同。虚拟机栈描述的是Java方法执行的内存模型:每个...
  • merrylilili
  • merrylilili
  • 2017年07月12日 11:36
  • 456

输出程序Crash时的详细堆栈信息(四)

原文地址:http://blog.sina.com.cn/s/blog_48f93b530100fzwt.html 前面几个方案都是直接定位crash的代码位置,但是在比较大型的程序中,只知道这个...
  • atceedsun
  • atceedsun
  • 2013年12月23日 17:35
  • 1781

JVM 内存基础概念之程序计数器与 Java 虚拟机栈和本地方法栈

前言 在上篇文章中,我们了解到 JVM 运行时数据区有五个区域,分别是:程序计数器、Java 虚拟机栈、本地方法栈、Java 堆、方法区。在这篇文章中,我们就来了解下程序计数器与 Java 虚拟...
  • Airsaid
  • Airsaid
  • 2016年02月01日 17:10
  • 1589
内容举报
返回顶部
收藏助手
不良信息举报
您举报文章:Java程序栈信息文件中的秘密(一)
举报原因:
原因补充:

(最多只允许输入30个字)