Practical DTracing
There is a simple reason why DTrace is such a great tool. I did the following steps while a production system ran at full speed at approx. 11:45 … at the highest load of the day (the storm right before before lunch).
The situation
Let’s assume you come to a customer and find such a situation.
</small>Your first thought is … “Damned, 0 percent idle and why is there such a high load of system calls”. The situation: In this system the customer started 7 JVMs. The application running in each JVM triggers a lot of threads to handle the user load. The application is called StrangeApp. I have to apologize here, because my notes aren’t complete or not usable for public usage …. so i’ve made up some numbers and changed names. But it should be sufficient to describe the path i used to find this problem.
Using DTrace
DTrace is a tool to answer questions, not a magic bullet that finds questions and answers them. So i will write this article by asking questions.
First question
Okay … first question “Dear DTrace, how many system calls of which kind are made by processes called StrangeApp?”
And DTrance answered:
</small>
Hmmm, yield()
calls galore.
Second question
Okay, annother question “Dear DTrace, what calls yield() that often in the Application?”. The answer of DTrace wasn’t read directly … i knew it would be longer thus i wrote it directly into a file:
</small>The output of that file is a little bit garbled. I just piped it through c++filt
:
</small>Okay … Java, it’s in the libjvm.so. At this moment i knew what the problem was.Or at least the alarm was ringing as loud as the signal horn at a fire engine…
</small></small>Let’s have a look into the source:
</small>Okay … no wonder that there are so many yield calls …. let’s go up the stack and let’s find out what is calling this function in the great way of things. I’ve opted to find out about about “ParNewGenTask” albeit i did knew at that moment that i was a part of the Garbage Collector (Parallel New Generation is really obvious when you know a thing or two about Garbage Collection).
A grep
for ParNewGenTask confirmed that …
</small>
/gc_implementation
… the place where the wild things are …
Third question
I had another question for DTrace … “Dear DTrace, what threads are calling yield() that often”. I wanted to know if this yield calls are just made by certain threads or if they were made by all threads doing just their work.
</small>
Ask Google
Just seven threads and this pattern repeated for each JVM, otherwise there were almost no other yield calls. The yield() was really just triggered by certain threads and the number of threads was equal to the number of CPUs. That is enough information to feed Google with it, and a short search yielded the solution. The first hit when searching for “garbage collection threads cpu” yielded :
"By default on a host with N CPUs, the throughput collector uses N garbage collector threads in the minor collection."
Okay … 7 JVMs are starting 7 garbage collection threads each … 49 garbage collection threads. And that led me to write “About Java, parallel garbage collection and processor sets”