3

I have take thread dumps of my application deployed in production, which uses logback. I am NOT expert in analysing thread dumps, however, I am required to do so. I am learning it, and have read some online articles.

The below is the real thread dumps:


"logback-8" #136 daemon prio=5 os_prio=0 tid=0x00007f3588001000 nid=0x13a waiting on condition [0x00007f35f8e7b000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000068d740338> (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:1088)
        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:745)

"logback-7" #135 daemon prio=5 os_prio=0 tid=0x00007f356c030800 nid=0x139 waiting on condition [0x00007f35f8d7a000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000068d740338> (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:1088)
        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:745)

"logback-6" #134 daemon prio=5 os_prio=0 tid=0x00007f357c018000 nid=0x138 waiting on condition [0x00007f3568ef0000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000068d740338> (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:1088)
        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:745)

"logback-5" #133 daemon prio=5 os_prio=0 tid=0x00007f36b8003800 nid=0x137 waiting on condition [0x00007f35f9380000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000068d740338> (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:1088)
        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:745)

As I can see, most of these threads are in WAITING state.

But how do i know what exactly are they waiting for? Are these all threads trying to "wait" on "something"?

I did read some online materials , but when seeing a real thread dumps, it is not making any sense to me as how to take steps in understanding, as to what exactly these threads are trying to do, and at what thing are they WAITING, BLOCKED etc.

Can anyone please help me understand this?

CuriousMind
  • 8,301
  • 22
  • 65
  • 134
  • Do you use any kind of java framework like Spring or thread pooling ? – Saurabh Sep 10 '19 at 04:32
  • Yes , using spring framework. The above threads are related to log back, a logging Framework – CuriousMind Sep 10 '19 at 04:37
  • 1
    Looks like those particular threads are blpckedcon getting object (possibly log message) from an empty blocking queue. So in that particular case you do not need to worry since this is a pool of logging threads waiting to actually process log calls from your code – Ivan Sep 11 '19 at 20:45
  • @Ivan: Thanks for your comment. It seems so, however, how are your able to analyse it ? I am looking inputs on how to understand and makes sense of these dumps. In particular, what are those "hex" values? Where can I know about them? Can you expand a more? – CuriousMind Sep 13 '19 at 18:13
  • 1
    @CuriousMind, first thread names start with **logback-**. This is a hint that they were created by logback logging framework. Second, they wait on `DelayedWorkQueue.take()` which might mean that they are trying to get item from an empty blocking queue. You can check more information here https://stackoverflow.com/questions/7599608/how-to-analyze-a-java-thread-dump or simply google – Ivan Sep 13 '19 at 18:33

3 Answers3

1

As far as I have analyse thread dumps, When you are using such frameworks like Spring or other library like you have used here Logback. They create thread pool based on your configuration. For example, you can find such configuration in applicationcontext.xml or any of your java based configuration class. So, what it does is, it will create that much of threads at application startup or first initialisation call. If any task comes, then framework will pick one thread from pool and assign it. After completion of the task thread will come back in the pool and at that time the thread status would be like WAITING (parking) . This does not mean that it is block by any thread. It will not cause any performance headache if your server is capable enough to handle such pool. They are just sitting ideal because they do not have any task to do.

You can find more info on this and if you want to see visual way of analysis of your thread dump then you can use this. I found this site very helpful. Just upload your dump file.It will tell every thing that needed to be known by that thread dump.

Saurabh
  • 882
  • 1
  • 5
  • 16
1

Based on the above stack trace, these are the following inferences

  • There is a queue Q.
  • N number of jobs(Runnables) are added to the queue.
  • These jobs will be taken from the queue and executed by the threads in the ThreadPoolExecutors(It can be cached/Dynamic).

Lets assume, we have a thread pool Executor with only two threads(Fixed Size) and you have submitted only one job to the queue.(Job1)

Thread1 takes the job1 from the queue and execute. Once the execution is over, It goes to the WAITING state because there are no elements in the queue. It has no work to do. Presence of waiting threads on Stack trace doesn't imply they are harmful.

Diya
  • 127
  • 1
  • 9
0

First thing you may look to do is to search for Runnable thread and the synchronizers that it has locked. Runnable thread if hangs on for a long time there is a great chance for it to be performing IO or DB operations. Take subsequent thread dumps with Interval of 30 seconds or so and do a comparative study.

ujjwal shukla
  • 3
  • 2