13

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.

MartinTeeVarga
  • 10,478
  • 12
  • 61
  • 98
  • Are you trying to tell us that your `query()` method is waiting for something on `NOOP`? – Germann Arlington Apr 20 '15 at 12:04
  • 3
    Is your `query` method doing anything on its own, besides calling sub-methods ? – Olivier Croisier Apr 20 '15 at 12:04
  • Is there any synchronization in `query`, `method1` or `method2` you know of? – MrSmith42 Apr 20 '15 at 12:06
  • @OlivierCroisier no, the method is doing nothing else that those two calls. Edited the question. – MartinTeeVarga Apr 20 '15 at 12:06
  • 2
    This is interesting but unable to reproduce until you give us more information. – Alex Salauyou Apr 20 '15 at 12:07
  • OK. I assume none of those sub-methods are declared `synchronized` ? – Olivier Croisier Apr 20 '15 at 12:07
  • Are the sub methods returning anything back? – cyber_rookie Apr 20 '15 at 12:07
  • @SashaSalauyou I do not have a specific problem with a code. I am looking for a way to find the problem. – MartinTeeVarga Apr 20 '15 at 12:08
  • Possible that method1() or method2() can be synchronized on a mutex. Once the execution starts, it finishes quick, but it probably takes time for it to start due to lock on the mutex. – Pavan Kumar Apr 20 '15 at 12:08
  • 3
    If you dump a stack trace, it should tell you which thread is waiting for which monitor. – biziclop Apr 20 '15 at 12:09
  • Run it in the debugger, and create or simulate some load. Pick a worker thread at random and pause it. If it's inside `method1` or `method2`, then resume it, and try another, until you find one that's waiting in `query`. Then look at what it's waiting on. (Note: this might not work if your debugger won't pause waiting threads) – user253751 Apr 20 '15 at 12:09
  • Visual VM is a good tool to see method CPU usage, threads contentions ... http://docs.oracle.com/javase/7/docs/technotes/guides/visualvm/ – Michael Laffargue Apr 20 '15 at 12:10
  • @biziclop this sounds interesting, if you could please expand it to an answer... – MartinTeeVarga Apr 20 '15 at 12:10
  • @sm4 I don't think this warrants an answer, as I provided almost no added value, but here's a sample output from `jstack`: http://stackoverflow.com/questions/18161649/interpreting-jstack-output – biziclop Apr 20 '15 at 12:12
  • @MichaelLaffargue I am using VisualVM for profiling, and it tells me the self-time. How do I use it to find the problem then? I guess something that `biziclop` mentioned – MartinTeeVarga Apr 20 '15 at 12:12
  • :@sm4 In VisualVm you can click the `Thread Dump` button on the `Threads` page. – biziclop Apr 20 '15 at 12:13
  • Try to set the number of workers to the number of cores minus 2. – Joop Eggen Apr 20 '15 at 12:15
  • FWIW: I use YourKit Java profiler https://www.yourkit.com/java/profiler/ . There's an option to record thread monitors. It'll show which threads are being blocked/waiting, whose blocking them and what they're blocked on. – MadConan Apr 20 '15 at 12:16
  • You could do it the hard way, or the easy way. Check [*here*](http://stackoverflow.com/a/317160/23771). – Mike Dunlavey Apr 20 '15 at 15:00
  • 2
    I generally capture multiple thread dumps (5 at least) at a regular interval of 5 sec and then use Thread Dump Analyzer (https://java.net/projects/tda) to monitor the thread state. Thread dump should show you clearly if there is a monitor on which most of the threads are blocked . Otherwise it will show you if all the threads are waiting for different monitors of similar nature. When analyzed over multiple dumps, you will be able to understand if there is any long running thread. Please free to change frequency at which you capture the dump based on the initial set of observations. – Arnab Biswas Apr 21 '15 at 01:58
  • OK, you are getting stack traces and examining them carefully. Now if you examine the source code lines on the stack one or two levels up or down from where `method1` is calling out, you can see if what you're having it do might be avoided. If so, *and if you see it on more than one trace*, you've found your speedup. – Mike Dunlavey Apr 22 '15 at 14:52

4 Answers4

5

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.

Synesso
  • 37,610
  • 35
  • 136
  • 207
1

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.

MartinTeeVarga
  • 10,478
  • 12
  • 61
  • 98
0

Your best option is to find a way to get a stack trace of the running program. Here is one possible way.

Community
  • 1
  • 1
Tyler Scott
  • 1,046
  • 17
  • 33
  • 1
    You're right, except you should do it multiple times, like 10 or 20. If you only see a problem on one sample it doesn't say much, but if you see it two or more times, you can be sure it's substantial. – Mike Dunlavey Apr 22 '15 at 12:25
0

I suggest running the program using the debug mode in your IDE and put break points next to what may appear to be the problem. Then step into (e.g. F7 in Netbeans) at the point where the program makes a delay. You can step in all the way to obfuscated code though you may not be able to fix the issue there. However you will have known where the delay is.

microtone
  • 496
  • 3
  • 4
  • You're close to the right answer. Don't plant a break point in the code, because that requires you to make a prior guess what the problem is. Rather, interrupt it manually at random, multiple times, and each time see what it's doing, and single-step if you want. The interrupts will automatically be drawn to the problem code. See [*here*](http://stackoverflow.com/a/378024/23771). – Mike Dunlavey Apr 22 '15 at 12:30