What do you do when your Garbage Collection runs all the time? Well usually you would try to introduce some magic GC parameters to fix your issue. But let me tell you: Excessive garbage production cannot be fixed by parameters!
You use the parameters to tune an “ok” GC to become a “good” GC. In complex applications it is very easy to lose control over your garbage. I have seen logs where gigabytes of garbage is produced in a second. Visualized it looks like this:
But usually it happens only in production, or, if you are lucky, maybe even in load testing, but the main problem remains: How can you figure out what kind garbage is produced? Garbage leaves no trace.
There are a few possible ways to do that:
- Take a heap dump. Use a tool like Eclipse MAT to inspect the references of garbage.
This works. But taking a heap dump will stop your machine for a while, so you do not want to do that in production. Also, it is limited in what it sees. Maybe your timing is bad and you take the heap dump right after a GC when there is no significant garbage in memory. Even if there is garbage, you will never really know if that is really the biggest contributor.
- Use a profiler like JProfiler. Allocation profiling however is actually quite expensive and requires a lot of tuning to bring the overhead down. Even then it is risky to run in production. Using it on a development machine works, but still you might be unsure if that object creation you are looking at is really creating the garbage you can see from your GC logs.
- Add logging. This is for the desperate. The amount of logging and additional bookkeeping usually creates a lot of additional pressure on memory and GC as well as log file pollution. Also it requires deployment of many temporary debugging versions.
I did not like any of those solutions, so I decided to create my own tool. Maybe somebody else has done this already, but in that case I was unable to find it.
I created and open sourced Allocation Tracker.
Allocation Tracker is a performance and production optimized object creation counter. All it does is to add a counter to each
call of a class matching a given prefix. It is very fast on startup, where it does load time byte code manipulation. And it is very fast on object creation, where it only adds a counter per class name. It is also designed to consume very little memory.
After startup it does nothing until turned on via JMX. Eventually you want to look at what has been recorded. That functionality is also exposed via JMX.
At codecentric we use the Vaadin Framework a lot. We also contribute back features and optimizations. When starting our application with
com.vaadin classes will get instrumented.
After letting the tracker work for about a minute while working with the application, we can generate a report of the most frequently created instances:
com/vaadin/server/EncodeResult 102800 com/vaadin/server/AbstractClientConnector$AllChildrenIterable 9442 com/vaadin/server/AbstractClientConnector$CombinedIterator 9442 com/vaadin/util/CurrentInstance 3507 com/vaadin/event/ConnectorEvent 3445 com/vaadin/shared/communication/SharedState 1703 com/vaadin/shared/AbstractComponentState 1693 com/vaadin/server/ClientConnector$AttachEvent 1598 com/vaadin/server/ClientConnector$DetachEvent 1460
Do not get confused by the slashes, that is bytecode speak. As a developer you usually use dots instead.
So Vaadin produces a lot of
EncodeResults. No surprise for me. I have contributed a few patches already on this, because the encoding showed up as a CPU hotspot in profiling. Version 7.1.15 used here for profiling does not have them merged yet.
What was a surprise for me, however, is the sheer amount of
The code doing that can be seen in AbstractClientConnector#L582.