Tuesday, April 17, 2012

Howto use the CLRProfiler

Earlier this year I gave CLRProfiler a try. I found a few bad corners in my code, in which  unnecessary garbage is produced. I reduced garbage collection to about one collection every two or three minutes. Lately I wrote much new code, so I checked again. The garbage collection time line statistic looked like this:

One collection every 2.5 seconds! Not good!
Now I will explain how you can find the part of the code where the garbage comes from. First of all, you can see that the peeks are all orange, which means that the problem comes from string allocation (see the legend right). This is very common in .NET, because strings are immutable objects, which means, that you get a complete new string on the heap every time you concatenate strings without using the StringBuilder. So how to find the code that causes the problem? In the Time Line window, mark the timespan which you want to inspect, like in the picture below.


With a right click the context menu opens, where you select "Show Who Allocated". This opens the next windows, which shows what data was allocated in the marked timespan. Nice!


You can see in the top right corner, that 1,2MB of string data were allocated in the interval. If you look further left, along the fat pink line, you can see also who allocated the string data. In the class SunBurnGraphicsModel in the method PreDraw, a call (or calls) to StringBuilder.Append are causing the problem. Heres the relevant part of the PreDraw code (SbText is a StringBuilder):
m_infoBox.SbText.Clear();
// draw team number
m_infoBox.SbText.Append("Team ");
m_infoBox.SbText.Append(m_teamNumber);
m_infoBox.TextColor = TeamColors[m_teamNumber];
m_scene.InfoTextDrawer.SubmitInfoBox(m_infoBox);

So whats the problem? Its this line:
m_infoBox.SbText.Append(m_teamNumber);

Sadly thats equivalent to this (which I didn't knew):
m_infoBox.SbText.Append(m_teamNumber.ToString());

I thought that if StringBuilder has a method Append(int), this method won't call ToString(). But thats exactly what it does, meaning that every time the line is called, a new string gets allocated on the heap.
Now the line gets called every frame for every game object. My test level contains 500 objects. The size of a string in .Net is 20 byte + (size / 2) * 4byte (size / 2 rounded down). With size=1 that means that every frame 500 * 20byte = 10.000 byte of garbage gets produced. In 2.7 seconds (with average 55 frames/second) thats 150 frames * 10.000 byte = ca. 1.4MB of "1", "2" and "0" strings (all the possible team numbers)! Thats roughly the number which you can see in the allocation graph.

The Solution:
After googling some time I found this blog with a very nice description of exact my problem. Gavin Pugh wrote some extension methods for StringBuilder which avoid this problem. I only had to change the problematic line of code to this, to get rid of the problem completely:

m_infoBox.Text.Concat(m_teamNumber, 1);

After that, the garbage collection time line looked like this:

All the string allocation are gone. Ca. 12 seconds between two garbage collections. Still a bad value, but much better then before.
I part two I will show you some more typical "garbage" code I found.