2

I have specific trouble with performance, so started to profile my app, i see wondering stats in Jprofiler - Thread.run has up to 20% of CPU time in Call Tree analysis, and going to inner calls not represent his time (mostly near 0%). Seems line Thread.run itself takes 20%..

What it means, probably somewhere is an overhead of thread creation?, please advise

enter image description here

Fagoter
  • 559
  • 1
  • 7
  • 17
  • Do you have a spin-wait somewhere in a run-method? – Fildor Apr 04 '17 at 14:50
  • nope, no waits, no sleeps – Fagoter Apr 04 '17 at 14:51
  • 1
    Thread.run doesn't do anything, more likely this is an error in the account in the profiler. The overhead in Thread creation isn't measured by any profiler that I know of as it occurs in native code before the thread starts. Are you creating lots of very short lived threads? If so, use a thread pool instead. These days I rarely create thread directly and create a thread pool even if it is only one. – Peter Lawrey Apr 04 '17 at 14:55
  • First - in JProfiler you can choose what states you are looking into - Runnable, Wait, All etc. Did you change it? by default it's Runnable. Second - the fact that the entire 20% is on the `run()` method simply means that the code inside the `run()` method consumes your CPU, and not any other method that is called from `run()` . Can you post the `run()` method? – paranoidAndroid Apr 04 '17 at 15:47
  • 1
    @PeterLawrey This is not an error, it's simply related to filter configuration. The run method is always profiled and everything up to the first class that matches the call tree filter configuration becomes part of the self time of the run method. – Ingo Kegel Apr 04 '17 at 16:29
  • @IngoKegel if you look at the source for Thread.run () this cannot explain a high percentage of cpu used. There is no loops for example. – Peter Lawrey Apr 04 '17 at 17:53
  • 2
    @PeterLawrey Maybe I have to rephrase it: The time is from classes that are between the thread entry point and the first class that is is profiled according to the filter settings. Think of a servlet engine and the actual servlet implemetation. If the classes of the servlet engine are filtered, the time spent in the container will end up in the Thread.run method. – Ingo Kegel Apr 04 '17 at 19:55
  • @IngoKegel that is a reasonable explanation. +1 – Peter Lawrey Apr 04 '17 at 20:14
  • 2
    @PeterLawrey It's actually a common source of confusion, so I will add a help icon next to the Thread.run method that explains this situation – Ingo Kegel Apr 04 '17 at 20:27
  • @Fagoter: There are *so* many questions on stackoverflow, asking how to make sense of profiler output. You'd think everyone would understand it by now. There's a simple intuitive way to find out what takes time, as [*this link*](http://stackoverflow.com/a/317160/23771) shows. – Mike Dunlavey Apr 05 '17 at 00:11
  • @MikeDunlavey Your suggestion is valid, and I use it as well to get an initial indication what a hanging process is doing. JProfiler itself has a thread dump facility that allows you to compare thread dumps. In any case I think that it's a misconception that interpreting data from a profiler has to be trivial. Interpreting X-ray images is also difficult, for example. Scientists use many measurement devices that require training and thoughtful analysis of their output. – Ingo Kegel Apr 05 '17 at 08:26
  • @IngoKegel: Thanks for your note. Actually, I agree with the comparison of x-ray images to profiler output. An x-ray image is a 2d shadowgram of a 3d object, so it takes a lot of expertise to separate the layers. 3d techniques like CAT and MRI exist because 2d is insufficient. Same with profilers. The problem is not the stack sampling; the problem is the output, which merges the samples together into statistics of various kinds. That merging [*hides the crucial information*](http://stackoverflow.com/a/25870103/23771). Just let people see a random selection of the samples. – Mike Dunlavey Apr 05 '17 at 12:48
  • @MikeDunlavey That only works in a limited number of scenarios, mostly for algorithms. When you profile business software, you need the cumulation over time to delineate use cases and without visualizations like call trees, hot spots with backtraces and call graphs you would not get any kind of insight. Also, it's not just about methods, but about payloads (like SQL statements) and context (like URLs) and you cannot see those in stack traces. Btw, I don't think that CT/MRI requires less expertise than X-Ray. – Ingo Kegel Apr 05 '17 at 13:12
  • @IngoKegel: "payloads (like SQL statements) and context (like URLs) and you cannot see those in stack traces". That's why I do it under a debugger. I can see everything. – Mike Dunlavey Apr 05 '17 at 14:06
  • @MikeDunlavey OK, more power to you. Normal developers cannot do this :-) – Ingo Kegel Apr 05 '17 at 19:58

1 Answers1

3

The run method invoked by a thread is always profiled, regardless of whether the class of the Runnable is profiled.

From there on, everything up to the first class that matches the call tree filter configuration becomes part of the self time of the run method.

To see all classes, use "Sampling" as the call tree recording method and select the "Disable all filters" check box next to the "Sampling" setting in the profiling settings.

Ingo Kegel
  • 42,759
  • 9
  • 65
  • 97
  • While true, this doesn't explain how on null condition and a method call could use a high percentage of cpu. – Peter Lawrey Apr 04 '17 at 17:54
  • in my opinion this is just a confusion about reading the profiling results. We'll know better once we see the code and a screenshot of the profiler – paranoidAndroid Apr 04 '17 at 18:07
  • @PeterLawrey Please see my comment above – Ingo Kegel Apr 04 '17 at 19:55
  • Added screenshot above into post – Fagoter Apr 05 '17 at 08:25
  • @Fagoter The screenshot shows that it's definitely your filter settings. There's a framework or container in between the Runnable and the classes that you see in the first level below Thread.run. – Ingo Kegel Apr 05 '17 at 08:30
  • @IngoKegel i have pretty match default setup of JProfiler, just started to use it, so not clearly understand what filters you mean? How i can understand what is inside of this 20%, plz advice – Fagoter Apr 05 '17 at 08:56
  • @Fagoter Please follow the advice at the end of my answer – Ingo Kegel Apr 05 '17 at 09:34