2

In JProfiler, in the Call Tree and Hot Spots views of the CPU profiler, I have found that JProfiler is showing some methods as hot spots which aren't really hot spots. These methods are skewing my profiling work, as they are dominating these CPU views and making all other CPU consumers appear insignificant.

For example one thread is performing a Thread.sleep(300_000L) (sleeping for 5 minutes), and then doing some relatively minor work -- in a while(true) loop. JProfiler is configured to update the view every 5 seconds, and I have set the thread status selector to "Runnable". Every 5 seconds when JProfiler updates the view, I would expect the total self-time for the method to remain relatively small since the thread is sleeping and not in a runnable state, however instead I see the self time increment by about 5 seconds which would indicate (incorrectly) that the entire 5-second interval, the thread was in the runnable state. My concern is that the tool will be useless for my CPU profiling purposes if I cannot filter out the sleeping (Waiting) state.

With some testing, I have found that when the Thread.sleep() call eventually terminates, the self time drops down to near-zero again, and begins climbing again with the next invocation of Thread.sleep(). So to me it seems JProfiler is counting the method stats for the current invocation of Thread.sleep() as Runnable -- until the method actually terminates and then these stats are backed out of.

Is this a bug in JProfiler? Is there a way to get JProfiler to not count Thread.sleep() towards the Runnable state, even for long-running invocations of Thread.sleep()?

I am using a licensed version of JProfiler 8.1.4. I have also tried an evaluation version of JProfiler 10.1.

Update:

Here is a simple test case which exhibits this problem for me. I discovered that if I move the Thread.sleep() call to a separate method the problem goes away (see the in-line comments). This is not a great workaround because I'm profiling a large application and don't want to update all of the places where it calls Thread.sleep().

public class TestProfileSleep {

  public static void main(String... args) {
    new Thread(new Runnable() {
      private void sleep(long millis) throws InterruptedException {
        Thread.sleep(millis);
      }
      public void run() {
        try {
          while (true) {
            Thread.sleep(60_000L);  // profiling this is broken
            //sleep(60_000L); // profiling this works
          }
        }
        catch (InterruptedException ie) {
        }
      }
    }).start();
  }

}
JimN
  • 3,120
  • 22
  • 35
  • This is not the intended behavior of JProfiler and we cannot reproduce it, neither with JProfiler 8.1.4 nor with JProfiler 10.1. The problem must be triggered by some special condition in your setup, please write to support@ej-technologies.com with more details about your Java version, platform and how you start profiling. – Ingo Kegel Mar 29 '18 at 11:28
  • Thanks @IngoKegel for confirming this is not the intended behavior. I'll contact your support team and provide some additional information. – JimN Mar 29 '18 at 18:53
  • I have written a service that does nothing but a Thread.sleep(1000) and the JProfiler view doesn't show this time as neither "self time" nor "average time", I was expecting to see 90,000 milliseconds for 90 calls but instead it shows 22,080 microseconds, why is that behavior? does JProfiler not count the time that Thread.sleep does? thanks – Diego Ramos May 05 '22 at 01:52

0 Answers0