JAVA Thread Dump file analysis

The Thread Dump is introduced

Thread Dump is a very useful tool for diagnosing Java application problems. Each Java VM has the ability to generate thread-dumps of all threads at a certain point in time. Although the thread dumps printed by each Java VM are slightly different, most of them provide all information about each thread. For example: Thread status, thread Id, native Id, thread name, stack trace, priority.

The Thread Dump characteristics

  1. It can be used under various operating systems

  2. Can be used under a variety of Java application servers

  3. It can be used in production environments without affecting system performance

  4. Problems can be located directly on the application’s line of code (useful for troubleshooting problems online)

What online problems can it help us solve?

Thread dump can help you locate things like CPU spikes, non-responsiveness in your application, response time lag, Thread hangs, and high memory consumption.

How to fetch Thread Dump

When the server hangs, crashes, or is performing poorly, the Thread Dump of the server needs to be captured for subsequent analysis. In practice, one dump is not enough to confirm the problem. To reflect the dynamic changes of thread status, you need to perform threaddump multiple times with an interval of 10-20 seconds. It is recommended that at least three times of threaddump information be generated. If each time the dump information points to the same problem, the typicality of the problem is determined.

To get the thread dump

JDK take command line tools for PID, and then obtain ThreadDump: 1. The JPS or ps - ef | grep Java (for PID) 2. Jstack [l]<pid>| tee - a jstack. Log (get ThreadDump)Copy the code

Field practice

Getting the Thread dump for all threads is a two-step process.

  • The first step is to get the PROCESS PID

Use Jps to get information about all Java processes

  • The second step is to select the corresponding PID, such as the number string in the red box above. Use Jstack to obtain the information of all thread stacks
jstack  -l  9468 | tee -a jstack.log

Copy the code

Log Field Analysis

To understand this, the Thread dump file is divided into two parts

Take our example:

// The header information contains the current time JVM information
2021-01-14 17:00:51
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

Copy the code
// Thread info block
"ajp-nio-8019-exec-7" #75 daemon prio=5 os_prio=0 tid=0x00007fa0cc37e800 nid=0x2af3 waiting on condition [0x00007fa02eceb000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f183aa30> (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.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

Copy the code

Thread info block parameter meaning:

  • Thread name: AJP-NIO-8019-EXEC-7

  • Thread type: Daemon

  • Priority: The default value is 5

  • JVM Thread ID: tid= 0x00007FA0CC37E800, the unique identifier of a Thread within the JVM (obtained from java.lang.thread.getid (), usually implemented as an increment).

  • Corresponding system thread ID (NativeThread ID) : nid=0x2af3, which corresponds to the thread PID of the top command, but one is in hexadecimal and the other is in hexadecimal. (Run the top -h -p pid command to view information about all threads of the process.)

  • State: Java.lang.thread. State: WAITING (parking)

  • Thread call stack information: For code analysis. Stack information should be read from the bottom up because the order of program calls is from the bottom up.

Native Thread Status

System threads have the following states:

  • deadlock

A deadlocked thread usually refers to a situation in which multiple threads occupy each other’s resources during invocation and cannot be released.

  • runnable

Generally, the thread is in the executing state. The thread occupies resources and is performing an operation, such as querying the database through SQL statements or writing to a file.

  • blocked

A thread is in the blocked state. During the execution of the current thread, the required resources are waiting for a long time but cannot be obtained. This state is identified by the thread manager of the container as the blocked state, which can be understood as the thread waiting for the resources to timeout.

  • waiting on condition

The thread is waiting for a resource or a condition to occur. The specific reason needs to be analyzed in combination with the following stack information.

(1) If the stack information is clearly the application code, it proves that the thread is waiting for resources. Generally, when a resource is read in large quantities and the resource is locked, the thread enters the waiting state, waiting for the resource to be read, or waiting for the execution of other threads.

(2) If a large number of threads are found in this state, and the stack information indicates that they are waiting for network read and write, it is because the thread cannot execute due to network congestion, which may be a sign of a network bottleneck:

The network is very busy, almost consumes all the bandwidth, there is still a lot of data waiting for network read and write; The network may be idle, but packets cannot arrive due to routing or firewall problems. Therefore, some performance observation tools of the system must be used for comprehensive analysis. For example, netstat statistics the number of packets sent per unit time to see whether it obviously exceeds the limit of the network bandwidth. Observe the CPU usage and check whether the CPU time in system mode is significantly higher than that in user mode. These all point to network bottlenecks caused by limited network bandwidth.

(3) Another common case is that the thread is in sleep, waiting for the time of sleep to wake up.

  • Waiting for monitor entry or in object.wait ()

Moniter is Java’s main tool for achieving mutual exclusion and collaboration between threads. It can be thought of as a lock on an object or class. Each object has only one Monitor.

As can be seen from the figure above, each Monitor can only be owned by one Thread at a certain time, which is an “Active Thread”, while other threads are all “Waiting threads “, Waiting in two queues “Entry Set” and “Wait Set” respectively. The state of the waiting thread in “Entry Set” is waiting for monitor Entry, and the state of the waiting thread in “Wait Set” is in object.wait ().

(1) Threads in the “Entry Set”. We call the code segment protected by synchronized a critical section, and the corresponding code is as follows:

synchronized(obj) {

} 
Copy the code

When a thread requests Entry to a critical section, it enters the “Entry Set” queue, and there are two possibilities:

  • The Monitor is not owned by other threads, and there are no other waiting threads in the “Entry Set”. This thread becomes the Monitor Owner of the corresponding class or object and executes the code in the critical section. The Thread Dump shows that the Thread is in the “Runnable” state.
  • The Monitor is owned by another thread waiting in the “Entry Set” queue. The Thread Dump shows that the Thread is in a state of “waiting for monity entry”.

Critical sections are set up to ensure atomicity and integrity of code execution within them, but because critical sections only allow threads to pass serially at any given time, this is the opposite of the original purpose of multithreading. Excessive use of synchronized in multithreaded programs, or inappropriate use of synchronized, can cause a large number of threads to wait at the entrance to a critical area, resulting in a significant performance degradation of the system. If you find this in Thread Dump, you should review the source code and improve it.

When a thread acquires the Monitor and enters the critical section, it calls the Wait () method of an object (usually a synchronized object) to discard the Monitor if the condition for the thread to continue running is not met. Enter the Wait Set queue. Only when another thread calls notify() or notifyAll() on the object do the threads in the “Wait Set” queue get a chance to compete, but only one thread gets the object’s Monitor and returns to the running state. Threads in Wait Set are in object.wait ().

In general, focus on threads in Runnable state when the CPU is busy, and on threads in waiting for Monitor Entry state when the CPU is busy.

JVM thread state

NEW:

For each Thread, there is a corresponding Thread object in heap memory. Thread t = new Thread(); When the Thread object is created in the heap, the Thread is in the NEW state before the t.start() method is called. In this state, a thread is no different from a normal Java object, just an object in heap memory.

A RUNNABLE:

This state indicates that the thread has all the running conditions, is in the run queue ready for operating system scheduling, or is running. Threads in this state are normal, but not if they stay in this state for long periods of time, indicating that the thread is running for a long time (performance issues), or that the thread is never executing (thread hunger issues).

BLOCKED:

A thread is waiting for a monitor to acquire a Java object (also known as a built-in lock), that is, a thread is waiting to enter a method or block of code protected by synchronized. Synchronized is used to ensure atomicity. Only one thread can enter the critical region at any time, and other threads can only queue up and wait.

WAITING:

** is in the state of the thread, waiting for an event to occur, only when certain conditions are met, can get the opportunity to execute. ** and this particular event is usually produced by another thread. That is, if no specific event occurs, the thread in that state will wait and not get the opportunity to execute. For example, thread A calls obj.wait(). If no thread calls obj.notify or obj.notifyAll, thread A cannot resume running. If thread A calls locksupport.park () and no other thread calls locksupport.unpark (A), there is no way for A to resume running.

TIMED_WAITING:

Many of the thread-related classes in J.U.C offer both time-limited and open-ended versions of the API. TIMED_WAITING means that the thread called a time-limited version of the API and is waiting for time to pass. When the wait time is over, the thread can resume running as well. If a thread is in a WAITING state, a special event must occur before it can resume running. A thread in TIMED_WAITING will resume running if a specific event occurs or if time has elapsed.

TERMINATED:

The thread remains in this state when it completes execution, returns from the run method, or terminates with a runtime exception. At this point, the Thread only has the Thread object, which is useless.

Analysis based on dump logs

Let’s analyze the dump log based on the actual code to get a more transparent understanding of why the thread is in this state

Example 1:

Waiting to release lock

package jstack;
 
 
public class BlockedState
{
	private static Object object = new Object();
 
	public static void main(String[] args)
	{
		Runnable task = new Runnable() {
 
			@Override
			public void run(a)
			{
				synchronized (object)
				{
					long begin = System.currentTimeMillis();
 
					long end = System.currentTimeMillis();
 
					// Let the thread run for 5 minutes and hold the object monitor all the time
					while ((end - begin) <= 5 * 60 * 1000) {}}}};new Thread(task, "t1").start();
		new Thread(task, "t2").start(); }}Copy the code

The thread that acquired the object first will execute for 5 minutes, and will hold the object monitor for 5 minutes, while the other thread cannot execute and is BLOCKED


"t2" prio=6 tid=0x27d7a800 nid=0x1350 waiting for monitor entry [0x2833f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at jstack.BlockedState$1.run(BlockedState.java:17)
        - waiting to lock <0x1cfcdc00> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:662)

"t1" prio=6 tid=0x27d79400 nid=0x1338 runnable [0x282ef000]
   java.lang.Thread.State: RUNNABLE
        at jstack.BlockedState$1.run(BlockedState.java:22)
        - locked <0x1cfcdc00> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:662)
Copy the code

As can be seen from Thread dump, the T2 thread is BLOCKED (on object monitor). Waiting for monitor entry to synchronized protected area, but obj’s monitor is owned by another Thread, so JVM Thread State is java.lang.thread. State: BLOCKED (on object monitor) indicates that the thread is waiting for resources.

Example 2:

A deadlock

public class DeadLock {
    
    public static void main(String[] args) {
        final Object resource1 = "resource1";
        final Object resource2 = "resource2";

        Thread t1 = new Thread(){
            public void run(a){
                synchronized(resource1){
                    System.out.println("Thread1:locked resource1");
                    try{
                        Thread.sleep(50);
                    }catch(Exception ex){

                    }
                    synchronized(resource2){
                        System.out.println("Thread1:locked resource2"); }}}}; Thread t2 =new Thread(){
            public void run(a){
                synchronized(resource2){
                    System.out.println("Thread2:locked resource2");
                    try{
                        Thread.sleep(50);
                    }catch(Exception ex){

                    }
                    synchronized(resource1){
                        System.out.println("Thread2:locked resource1"); }}}}; t1.start(); t2.start(); }}Copy the code

Thread dump: Thread dump: Thread dump: Thread dump: Thread dump: Thread dump: Thread dump


"Thread-1" #20 prio=5 os_prio=31 tid=0x00007fb76c0e1800 nid=0x9d03 waiting for monitor entry [0x0000700004dbf000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at DeadLock$2.run(DeadLock.java:35)
        - waiting to lock <0x000000076af61870> (a java.lang.String)
        - locked <0x000000076af618b0> (a java.lang.String)

"Thread-0" #19 prio=5 os_prio=31 tid=0x00007fb76c002800 nid=0x9e03 waiting for monitor entry [0x0000700004cbc000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at DeadLock$1.run(DeadLock.java:19)
        - waiting to lock <0x000000076af618b0> (a java.lang.String)
        - locked <0x000000076af61870> (a java.lang.String)

Copy the code


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007fb769825b58 (object 0x000000076af61870, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00007fb769823168 (object 0x000000076af618b0, a java.lang.String),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at DeadLock$2.run(DeadLock.java:35)
        - waiting to lock <0x000000076af61870> (a java.lang.String)
        - locked <0x000000076af618b0> (a java.lang.String)
"Thread-0":
        at DeadLock$1.run(DeadLock.java:19)
        - waiting to lock <0x000000076af618b0> (a java.lang.String)
        - locked <0x000000076af61870> (a java.lang.String)

Found 1 deadlock.

Copy the code

Example 3

Call wait(), the corresponding thread state of sleep()

    public static void main(String[] args) {

        Thread thread = new Thread(Thread 1 "") {
            // Override the run method
            public void run(a) {
                synchronized (this) {
                    System.out.println(Thread.currentThread().getName());
                    try {
                        wait();
                    } catch(InterruptedException e) { e.printStackTrace(); }}}}; thread.start();try {
            TimeUnit.SECONDS.sleep(3);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        synchronized (thread) {
            System.out.println(Thread.currentThread().getName());
            try {
                TimeUnit.SECONDS.sleep(60);
            } catch(InterruptedException e) { e.printStackTrace(); } thread.notify(); }}Copy the code

This code executes thread 1 run() and then blocks the block by calling wait(). Wait until the main thread calls thread.notify() to proceed. We exported the thread dump log file about 10 seconds after the program started running, at which point:

Os_prio =0 TID = 0x00007f420024D800 nID = 0x1CA5 in object.wait () [0x00007F41e71EE000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1) at java.lang.Object.wait(Object.java:502) at com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1.run(ObjectWaitingMock.java:15) - locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1) Locked ownable synchronizers: - None .... "Main" #1 prio=5 OS_PRIO =0 TID = 0x00007F420000D800 nID = 0x1C84 waiting on condition [0x00007f4209891000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at java.lang.Thread.sleep(Thread.java:340) at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386) at com.jvm.study.threaddump.deadlock.ObjectWaitingMock.main(ObjectWaitingMock.java:31) - locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1) Locked ownable synchronizers: - NoneCopy the code
  • [Thread 1] Thread: wait() is blocked, the State corresponds to in object.wait (), and the State details correspond to java.lang.thread. State: WAITING (on Object monitor).
  • [main] Thread: timeunit.seconds. Sleep (60) blocked, waiting on condition, State details java.lang.thread. State: TIMED_WAITING (sleeping).

Symptom analysis solution based on case

  • 1 The CPU usage is low but the response is slow

Thread Dump is performed several times throughout the request and then compared to get a list of threads that are BLOCKED, usually because they are stopped at I/O, database connection, or network connection.

  • 2 The CPU has a high load and slow response

Dump multiple times in one request Compared to the runnable thread that dumps files multiple times, if there is a large change in the execution method, it is normal. If you are executing the same method, there are some problems; First, find the process that occupies CPU, then locate the corresponding thread, and finally analyze the corresponding stack information. Use the above method several times at the same time, then do a comparative analysis to find the cause of the problem in the code.

  • 3 The request cannot be answered

Dump multiple times to check for Found one Java-level deadlock. Deadlocks often manifest as a stalled application or a process that no longer responds to user requests. On the operating system, the CPU usage of the corresponding process is zero and will soon disappear from the output of TOP or PRstat.

Concern public number: Java baodian