Creating Strings - A Case Study

  • [アーティクル]

I recently worked an issue with a customer who was experiencing high CPU. Performance Monitor data showed that the % of Time in GC was 46%. We generally recommend that you not be in GC more than 5% of the time, so this was a point of interest.

One of the common causes of very frequent GC is GC.Collect() being called. I checked the # of Induced GC Perfmon counter and it was greater than 8,000 with a process uptime of only a few hours. This was obviously a clear sign that someone was calling GC.Collect() a lot! ASP.NET will call GC.Collect() at times, but not nearly this often.

We found a DLL that was causing that problem and fixed it. Good news. Induced GC was now 0. Bad news. CPU and Time in GC were both still high.

Many issues that we work are like this; like peeling an onion. We resolve one part of the issue only to discover other problems coming to the surface. This was just such an issue. Once we resolved induced GCs, a pattern became clear.

Have a look at the Perfmon data shown below. The color-key appears below the image:

Perf

Red: % of Time in GC
Blue: % Processor Time
Tan: # of Bytes in All Heaps
Black: Large Object Heap Size

 

The first thing to notice is that things started out okay and then went bad very quickly. One of the things that can cause that pattern is a problem call stack. (In fact, that's the issue here. More soon.) We can also see that something is creating a lot of objects and that's causing considerable memory pressure. That's causing us to go into GC often, but even when we're not in GC, you can see that CPU remains high.

The first thing I decided to do was to check the Large Object Heap to see what we had there.

0:046> !dumpheap -min 85000 -stat

Statistics:

        MT      Count     TotalSize Class Name

0x000f3198         69    87,714,456      Free

0x03084300        123   158,192,160 System.String

Total 192 objects, Total size: 245,906,616

 

This tells me that the memory we see in the LOH is taken up by strings. In fact, when I looked at some of these strings in the debugger, they turned out to be XML data generated by the customer.

I then checked to see where one of these big strings was rooted. It was rooted in a thread, so I checked that stack and saw this:

0:053> kL

ChildEBP RetAddr 

0635b890 791c134c mscorsvr!wstrcopy+0x26

0635b8a4 035ac67c mscorsvr!COMString::FillStringChecked+0x37

 

This tells me that we're making a copy of a string, so I checked the managed stack. When I did, I found a couple of interesting problems. First of all, the customer had a function call that was recursive and had hundreds of iterations already. Secondly, I could tell that each iteration of that function created more strings via wstrcopy. This is a clear sign of string concatenation, and indeed, in another dump I could see concat being called.

In the end, the customer's allocation pattern caused memory pressure and caused us to go into GC much more often than we should have. (In particular, the customer was creating a large number of objects on almost a per-request basis.) Because of this, the customer experienced high CPU and poor application performance.

I hope this helps others who might see the same kind of thing in production applications.

Jim

Comments