How do I detect what is my method waiting for?

Question

I have a method in Java that call several other methods. This method is being called from several threads, in a fixed thread pool. The number of workers is the same as the number of available processors (cores).

public void query() {
    method1();
    method2();
}

When I profile the program execution using VisualVM the times of method1() and method2() times are very short, but query() self-time is very long. But the method has no other code apart from the two calls. There might be synchronization inside method1() and method2(), but nothing obvious in code that I have control of.

When I reduce the number of workers in the pool to 1, this self-time is almost gone. Both single-threaded and multi-threaded execution times of the whole program are almost the same. I think it means that my method query() is waiting for something.

There are no deadlocks, the execution finishes fine. The two methods method1() and method2() call a lot of other things including library classes in obfuscated jars, so it is not easy for me to debug it. However the query() method is called directly from the worker threads, using java.util.concurrent.ExecutorService.

Answer 1

Issue a kill command at level 3 against the running process. All threads will dump a stack trace to the standard out and the app will continue running.

kill -3 <pid>

Note, you wont see anything on the console where you issued the kill command. The Java app itself will have the output. You might need to check logs, depending on where the app is redirecting its output.

Answer 2

I have found the problem in a proxy class that was wrapping another class in a custom locking mechanism.

I went on creating a series of Thread Dumps. Since I was using JVisualVM for profiling, I created a handful of Thread Dumps during the process. Ctrl+Break worked too, same as kill -3 <pid> mentioned by Synesso in his answer.

I used the Thread Dump Analyzer mentioned in the comments to analyze them. I did not know what to look for first, but thanks to the linking of objects and monitors in the TDA, I found something like this:

"pool-9-thread-32" #304 prio=5 os_prio=0 tid=0x000000002a706800 nid=0x348c waiting for monitor entry [0x000000003f06e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.example.MyClass.method1(MyClass.java:400)
    - waiting to lock <0x0000000680837b90> (a com.example.DifferentClass)
    at com.example.MyClass.query(MyClass.java:500)
    ... omitted ...
    at java.util.concurrent.FutureTask.run(FutureTask.java:270)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:618)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x000000075bc59aa8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

DifferentClass extends abstract MyClass and there is a call from method1() to DifferentClass, where a DTO object is passed to a method that does a lot of processing, logging and finally saving to a database. The proxy class was used during the creation of one of the database handling classes.