Naked Thought

Cave Quisquiliae (Beware of Garbage!)

This week I was contracted by a local company to investigate why their windows service was getting slower and slower over time. They would start a long running process on the service which would start off processing 100 transactions a minute however after 15 minutes would only be processing 50 minute. In fact, after one hour it would be processing as little as 5 a minute.

Why the slow down? I was hired to find out!

Symptoms

The first thing I took a look at is any trends that were seen from Performance Monitor (perfmon.exe). Obviously something was going wrong - was it paging? Memory? Disk queuing? Mystical tumblbeasts gnawing at the servers?

Interestingly enough there were some noticable trends:

• Allocated bytes per second on the increase
• Gen 0, Gen 1 and Gen 2 Collections on the increase
• % Time in GC on the increase

The interesting one to note here is the percentage time spent collecting garbage was going up and up. I think we have a clear indicator!

Diagnosis

Obviously, if the system is spending more and more time doing garbage collection, it is spending less and less time doing the work your application is designed to do. This explains the symptom that was being seen: the number of transactions being processed getting lower and lower. So what makes the system spend more and more time in garbage collection? Well, more trash!

Since I love personifying things…

Every .NET application (or Java for that matter) has a dedicated “janitor” which goes around cleaning up trash. He’s quite a clever and effective this janitor: he knows what is trash and what is still being used. If it is still being used, he’ll postpone checking it during the next quick cleanup. He is only human (!) though - if there is too much trash then he isn’t going to be able to keep up and trash is going to start piling up around the place. In this case, he is going to be spending longer and longer wading through the rubbish and throwing away what isn’t needed! I guess if this goes on and on, he’ll eventually go into early retirement - taking your app with him!

Treatment

Now we have an idea about what’s wrong, the next step is to find out what is generating all of this trash to see if we can be a little more “environmentally friendly” with our usage of objects! I’ve used a few memory profilers for .NET and one stands out from the rest: .NET Memory Profiler. After installing this I noticed a few things:

• String generation was incredibly high. This was largely from:
  • Cavalier use of String.Split (it was being used lazily)
  • There were a lot of unnecessary character to string conversions
  • String concatenations were used in some areas which were used inefficiently
• Object cloning of highly linked objects in caches (i.e. one object cached would generate 1000 new objects)
• Object construction was incredibly resource intensive for some object types. There was a lot of metadata which didn’t change between instantiations which was being re-generated every time
• Strings were being used in places where enumerations or value types would be better suited

Luckily this was all treatable. So off to work I went fixing this up. Some interesting changes:

• There were a lot of “quick wins” with strings. These were attacked first for a proof of concept. After attacking these, the transaction speed increased to 120 transactions per minute.
• The object cache worked much more effectively by serializing when entering and retrieving from the cache. The overhead of serialization was minimal compared to the overhead of cloning large objects. 
• Static metadata made an INCREDIBLE difference, namely due to the heavy use of these objects throughout the system.

After fixing just these things I noticed the difference of generation of new objects vs removed objects go from 30,000 over a ten minute period to -200 objects. Much much nicer to see!

To cut a long story short - not only did I end up fixing the problem, but the system sped up substantially. It was processing 150 transactions per minute without slowdown. All from taking an environmentally friendly approach to trash :-)

Conclusion

For most systems, this is unlikely to be a noticable problem however for enterprise systems I think it is important to consider every time you write a line of code. Every piece of code should be considered:

1. What objects are being created behind the scenes? 
2. Is this piece of code a core piece of logic? 

Obviously core logic being called often is going to generate trash at a faster rate!

In closing: “Beware of Garbage” when coding… even the highest end systems will notice slow down from too much trash.

^PM