欢迎您, 来到 宁时修博客.^_^

Java程序线上排查命令----02、jstack

2018/09/04 言则行 Java,linux命令 463
Java程序的问题排查命令

一、jstack的简介

    jstack 用于生成 java 虚拟机当前时刻的线程快照。线程快照是当前java虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待。 

    线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做什么事情,或者等待什么资源。 如果java程序崩溃生成core文件,jstack工具可以用来获得core文件的java stack和native stack的信息,从而可以轻松地知道java程序是如何崩溃和在程序何处发生问题。另外,jstack工具还可以附属到正在运行的java程序中,看到当时运行的java程序的java stack和native stack的信息, 如果现在运行的java程序呈现hung的状态,jstack是非常有用的。

    jstack命令主要用来查看Java线程的调用堆栈的,可以用来分析线程问题(如死锁)。


    官方文档:https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jstack.html



二、线程状态

    下面是使用jstack命令查看线程堆栈信息时可能会看到的几种线程状态:

NEW         未启动的。不会出现在Dump中。

RUNNABLE    在虚拟机内执行的。运行中状态,可能里面还能看到locked字样,表明它获得了某把锁。

BLOCKED     受阻塞并等待监视器锁。被某个锁(synchronizers)給block住了。

WATING      无限期等待另一个线程执行特定操作。等待某个condition或monitor发生,一般停留在park(), wait(), sleep(),join() 等语句里。

TIMED_WATING 有时限的等待另一个线程的特定操作。和WAITING的区别是wait() 等语句加上了时间限制 wait(timeout)。

TERMINATED   已退出的。



三、Monitor

    在多线程的 JAVA程序中,实现线程之间的同步,就要说说 Monitor。 Monitor是 Java中用以实现线程之间的互斥与协作的主要手段,它可以看成是对象或者 Class的锁。每一个对象都有,也仅有一个 monitor。下面这个图,描述了线程和 Monitor之间关系,以及线程的状态转换图:

thread.bmp


进入区(Entrt Set)    表示线程通过 synchronized 要求获取对象的锁。如果对象未被锁住,则迚入拥有者;否则则在进入区等待。一旦对象锁被其他线程释放,立即参与竞争。

拥有者(The Owner)    表示某一线程成功竞争到对象锁。

等待区(Wait Set)     表示线程通过对象的wait方法,释放对象的锁,并在等待区等待被唤醒。

    

    从图中可以看出,一个 Monitor在某个时刻,只能被一个线程拥有,该线程就是 “Active Thread”,而其它线程都是 “Waiting Thread”,分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”,而在“Wait Set”中等待的线程状态是 “in Object.wait()”。 先看 “Entry Set”里面的线程。我们称被 synchronized保护起来的代码段为临界区。当一个线程申请进入临界区时,它就进入了 “Entry Set”队列。对应的 code就像:

synchronized(obj) {
.........

}


四、调用修饰

    表示线程在方法调用时,额外的重要的操作。线程Dump分析的重要信息。修饰上方的方法调用。

locked <地址> 目标:使用synchronized申请对象锁成功,监视器的拥有者。

waiting to lock <地址> 目标:使用synchronized申请对象锁未成功,在迚入区等待。

waiting on <地址> 目标:使用synchronized申请对象锁成功后,释放锁幵在等待区等待。

parking to wait for <地址> 目标:需与堆栈中的"parking to wait for (atjava.util.concurrent.SynchronousQueue$TransferStack)"结合来看。first–>此线程是在等待某个条件的发生,来把自己唤醒,second–>SynchronousQueue不是一个队列,其是线程之间移交信息的机制,当我们把一个元素放入到 SynchronousQueue 中时必须有另一个线程正在等待接受移交的任务,因此这就是本线程在等待的条件。


    locked

at oracle.jdbc.driver.PhysicalConnection.prepareStatement- locked <0x00002aab63bf7f58> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.PhysicalConnection.prepareStatement- locked <0x00002aab63bf7f58> (a oracle.jdbc.driver.T4CConnection)
at com.jiuqi.dna.core.internal.db.datasource.PooledConnection.prepareStatement

    通过synchronized关键字,成功获取到了对象的锁,成为监视器的拥有者,在临界区内操作。对象锁是可以线程重入的。



    waiting to lock

at com.jiuqi.dna.core.impl.CacheHolder.isVisibleIn(CacheHolder.java:165)- waiting to lock <0x0000000097ba9aa8> (a CacheHolder)
at com.jiuqi.dna.core.impl.CacheGroup$Index.findHolder
at com.jiuqi.dna.core.impl.ContextImpl.find
at com.jiuqi.dna.bap.basedata.common.util.BaseDataCenter.findInfo

    通过synchronized关键字,没有获取到了对象的锁,线程在监视器的进入区等待。在调用栈顶出现,线程状态为Blocked。


    waiting on

at java.lang.Object.wait(Native Method)- waiting on <0x00000000da2defb0> (a WorkingThread)
at com.jiuqi.dna.core.impl.WorkingManager.getWorkToDo- locked <0x00000000da2defb0> (a WorkingThread)
at com.jiuqi.dna.core.impl.WorkingThread.run

    通过synchronized关键字,成功获取到了对象的锁后,调用了wait方法,进入对象的等待区等待。在调用栈顶出现,线程状态为WAITING或TIMED_WATING。


    parking to wait for

    park是基本的线程阻塞原语,不通过监视器在对象上阻塞。随concurrent包会出现的新的机制,不同synchronized体系不同。



    线程动作

    线程状态产生的原因:

runnable:  状态一般为RUNNABLE。

in Object.wait():  等待区等待,状态为WAITING或TIMED_WAITING。

waiting for monitor entry:  进入区等待,状态为BLOCKED。

waiting on condition:  等待区等待、被park。

sleeping:  休眠的线程,调用了Thread.sleep()。

    Wait on condition 该状态出现在线程等待某个条件的发生。具体是什么原因,可以结合 stacktrace来分析。 最常见的情况就是线程处于sleep状态,等待被唤醒。 

    常见的情况还有等待网络IO:在java引入nio之前,对于每个网络连接,都有一个对应的线程来处理网络的读写操作,即使没有可读写的数据,线程仍然阻塞在读写操作上,这样有可能造成资源浪费,而且给操作系统的线程调度也带来压力。在 NewIO里采用了新的机制,编写的服务器程序的性能和可扩展性都得到提高。 正等待网络读写,这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。一种情况是网络非常忙,几乎消耗了所有的带宽,仍然有大量数据等待网络读写;另一种情况也可能是网络空闲,但由于路由等问题,导致包无法正常的到达。所以要结合系统的一些性能观察工具来综合分析,比如 netstat统计单位时间的发送包的数目,如果很明显超过了所在网络带宽的限制; 观察 cpu的利用率,如果系统态的CPU时间,相对于用户态的 CPU时间比例较高;如果程序运行在 Solaris 10平台上,可以用 dtrace工具看系统调用的情况,如果观察到 read/write的系统调用的次数或者运行时间遥遥领先;这些都指向由于网络带宽所限导致的网络瓶颈。(来自http://www.blogjava.net/jzone/articles/303979.html



五、jstack使用

[root@test-web-server ~]#  jstack -help
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


    参数说明:

    1)options: 

    executable: Java executable from which the core dump was produced.(产生core dump的java可执行文件)

    core:将被打印信息的core dump文件。

    remote-hostname-or-IP:远程debug服务的主机名或ip。

    server-id:唯一id,假如一台主机上多个远程debug服务 。


    2)基本参数:

    -F :当jstack<pid>不响应时(进程挂起)使用,强制打印栈信息,一般情况不需要使用。

    -m : 打印java堆栈信息,及c/c++框架的堆栈信息(如native方法)。可以打印JVM的堆栈,显示Native的栈帧,一般应用排查不需要使用。

    -l  : 长列表,打印有关锁的其他信息。例如属于java.util.concurrent的ownable synchronizers列表,会使得JVM停顿得长久得多(可能会差很多倍,比如普通的jstack可能几毫秒和一次GC没区别,加了-l 就是近一秒的时间),-l 建议不要用。一般情况不需要使用。

    -h :或 -help打印帮助消息。

    pid :需要被打印堆栈信息的java进程id,可以用jps查询。



    使用示例:

[root@test-web-server ~]#  jstack 31941 | more
2019-06-19 02:50:12
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.131-b11 mixed mode):

"Attach Listener" #6703 daemon prio=9 os_prio=0 tid=0x00007f09b8002000 nid=0x1f94 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"logback-8" #5893 daemon prio=5 os_prio=0 tid=0x00007f08b4003800 nid=0x5e4 waiting on condition [0x00007f0895adf000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c9b6c2c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:748)

"logback-7" #5657 daemon prio=5 os_prio=0 tid=0x00007f08d8156800 nid=0x4eb6 waiting on condition [0x00007f0895be0000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006c9b6c2c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:748)

........................................................................

    一般情况下,通过jstack输出的线程信息主要包括:jvm自身线程、用户线程等。其中jvm线程会在jvm启动时就会存在。对于用户线程则是在用户访问时才会生成。

    每个线程堆中信息中,都可以查看到 线程ID、线程的状态(wait、sleep、running 等状态)、是否持有锁信息等。



六、jstack 案例分析

    jstack 查看线程具体在做什么,可看出哪些线程在长时间占用CPU,尽快定位问题和解决问题:

第一步:找出消耗CPU高的进程或线程
执行top命令,默认打开的是进程视图,PID是进程号。
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
31941 root      20   0   15.6g   3.0g  14284 S   0.7 10.0 118:12.73 java                                                                                                      
    1 root      20   0   52680   4852   2608 S   0.0  0.0   7:31.59 systemd 


或者执行top命令按 "Shift + h" 或按 "H" 打开线程视图,PID为线程号。
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                
11103 root      20   0  162684   2896   1620 R  0.7  0.0   0:00.35 top                                                                                                        
32003 root      20   0   15.6g   3.0g  14284 S  0.7 10.0  79:39.64 java 


第二步:找出进程内最耗费CPU的线程,可以使用
① ps -Lfp pid
② ps -mp pid -o THREAD,tid,time
③ top -Hp pid

使用第三个命令,输出如下:
$ top -Hp 31941
top - 03:25:41 up 61 days, 17:16,  1 user,  load average: 0.00, 0.01, 0.05
Threads: 116 total,   0 running, 116 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.0 sy,  0.0 ni, 99.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 31730160 total,  7929028 free, 19359096 used,  4442036 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 11633784 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                    
32003 root      20   0   15.6g   3.0g  14284 S  0.7 10.0  79:43.86 java                                                                                                       
32079 root      20   0   15.6g   3.0g  14284 S  0.3 10.0   9:17.08 java                                                                                                       
32081 root      20   0   15.6g   3.0g  14284 S  0.3 10.0   9:19.54 java                                                                                                       
31941 root      20   0   15.6g   3.0g  14284 S  0.0 10.0   0:00.00 java                                                                                                       
31942 root      20   0   15.6g   3.0g  14284 S  0.0 10.0   0:13.16 java
........................

TIME列就是各个Java线程耗费的CPU时间,CPU时间最长的是线程ID为32003的线程。


第三步:将线程ID转化为十六进制

$ printf "%x\n" 32003
7d03


第四步:使用jstack输出进程ID为31941的进程堆栈信息,然后grep线程ID为32003的十六进制ID。

$ jstack 31941|grep 7d03

在输出中可看到7d03线程在做什么。


比如示例:JVM调优之jstack找出最耗cpu的线程并定位代码(https://www.cnblogs.com/chengJAVA/p/5821218.html)

$ jstack 21711 | grep 54ee
"PollIntervalRetrySchedulerThread" prio=10 tid=0x00007f950043e000 nid=0x54ee in Object.wait()
可以看到CPU消耗在PollIntervalRetrySchedulerThread这个类的Object.wait(),定位到下面的代码:

// Idle wait
getLog().info("Thread [" + getName() + "] is idle waiting...");
schedulerThreadState = PollTaskSchedulerThreadState.IdleWaiting;
long now = System.currentTimeMillis();
long waitTime = now + getIdleWaitTime();
long timeUntilContinue = waitTime - now;
synchronized(sigLock) {
  try {
    if(!halted.get()) {
      sigLock.wait(timeUntilContinue);
    }
  } 
  catch (InterruptedException ignore) {
  }
}
它是轮询任务的空闲等待代码,上面的sigLock.wait(timeUntilContinue)就对应了前面的Object.wait()。



案例:

https://www.cnblogs.com/zhengyun_ustc/archive/2013/01/06/dumpanalysis.html

http://www.blogjava.net/jzone/articles/303979.html



点赞
说说你的看法

所有评论: (0)

# 加入组织

1、用手机QQ扫左侧二维码

2、搜Q群:1058582137

3、点击 宁时修博客交流群