3

In my ongoing investigation of high CPU usage in our application I have come to the conclusion that it's the GC taking up most of the CPU time. Looking at a memdump of the w3wp process (the app is iis hosted) I found something strange: there was a LOT of 46 byte large string objects on the heap, all of them dead and ready to be collected. Investigating further the following command: 

!dumpheap -mt 00007ff9bd160e08 -dead -min 2e -max 2e

Which dumps out all dead string objects of size 46 told me that I currently have 260000 dead strings of that size. Looking inside a few of them quickly revealed that all of them comes from the same place, a helper method that creats keys for our cache:

private static string Key(Guid ssoId)
{
    return string.Format("BasicUser:{0}-Brand:{1}", ssoId, MemBag.Client.BrandEnum);
}

The 46byte string is "BasicUser:" nothing more, at least as far as I can see:

0:000> !do 000000f1d48d49a0
Name:        System.String
MethodTable: 00007ff9bd160e08
EEClass:     00007ff9bca84860
Size:        46(0x2e) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String:      BasicUser:
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff9bd163980  40000ab        8         System.Int32  1 instance               10 m_stringLength
00007ff9bd1620f0  40000ac        c          System.Char  1 instance               42 m_firstChar
00007ff9bd160e08  40000ad       18        System.String  0   shared           static Empty
                                 >> Domain:Value  000000ee12ced200:NotInit  000000ee138a4440:NotInit  <<

All those allocations seems to be causing not just gen0 collections but a LOT of full collections as well, around 80-90% collections are full collections!

The method does get called a lot, but it makes no sense that it puts so much pressure on the GC! What is going on here? Is the method implemented in a bad way? how come is the string on the heap "BasicUser:" ? where is the rest of the string? even with empty params the "Brand" part is still missing.

I am very puzzled about this issue and really need some input here, any help is very appreciated!

Update

It seems like its always 10 chars long, I changed the code to:

  return string.Format("BasicUsr:{0}-Brand:{1}", ssoId, MemBag.Client.BrandEnum);

Changing User -> Usr, the result is that I now see strings like this on the heap :"BasicUsr:b" It seems to be the 10 first chars always, am I dumping the string out wrong?

Update 2

I got that chance to get a 1 minute perfview capture from the live server, this is what I got and if I am reading it correct we alloc huge big amounts of data which is the reason for the high mem pressure, almost every collection is gen2

Hard working GC

iCediCe
  • 1,672
  • 1
  • 15
  • 32
  • Version of .NET? 4.x or 3.5? – xanatos Aug 10 '15 at 09:13
  • What do you do with the strings after calling the method? – Sebastian Negraszus Aug 10 '15 at 09:15
  • 1
    Do you mean the 46 byte result string is the _return_ value of the Key() method?. If yes, then you definitely must investigate further: You must track what the calling client (who call the Key() method) _do_ the resulting strings. Probably the phenomena has nothing to do with the String.Format – g.pickardou Aug 10 '15 at 09:18
  • In .NET 2.0-3.5, the `StringBuilder.AppendFormat` (that is internally used by the `string.Format`) creates a temporary `char[]` array duplicating there the format string (so the one you pass)... In .NET 4.0 this was removed. – xanatos Aug 10 '15 at 09:20
  • In general, you should remember that `string.Format` is more flexible than fast. For small string concatenations it is probably faster to simply use the `+` operator. – xanatos Aug 10 '15 at 09:21
  • @xanatos Sorry for the missing info, its .NET 4.5 (4.0.30319.34209) running X64, would using + not put even more pressure on the GC? – iCediCe Aug 10 '15 at 09:23
  • @g.pickardou no the 46 byte string could not be the return as the return string always at least would contain the word "Brand" as well.. – iCediCe Aug 10 '15 at 09:24
  • 1
    @iCediCe in the end you would have to benchmark it... I do think that the `+` operator (that uses the `string.Concat` internally) should be a little faster and use a little less memory, but it is more a hunch than anything – xanatos Aug 10 '15 at 09:32
  • 1
    I would definitely try the following diagnostics: Change in the string.Format line the BasicUser: part to BasicXXXUser: , then reexamine a the memory. We must ensure that _really_ that code part causes the issue. – g.pickardou Aug 10 '15 at 09:34
  • @g.pickardou Tried changing it all ready, the code I posted IS responsible for the strings. – iCediCe Aug 10 '15 at 11:02
  • `m_stringLength` is 10 so this appears to be the full string. Not a problem with dumping. Looks like something else is generating those shorter strings. I don't think string.Format has a reason to generate such strange strings as temporaries. In any case Concat is way faster and more efficient. Use that. – usr Aug 10 '15 at 11:40
  • @usr Ok, I will try concat and see if it helps. – iCediCe Aug 10 '15 at 12:18
  • "strings in cache", cache is the problem word. High odds that cached strings can make it into gen #2. But yet you don't seem to use the cache very efficiently given the very high allocation rate and the modest total memory usage. Lots of gen #2 collections are the result. – Hans Passant Aug 10 '15 at 13:38
  • @HansPassant You might very well be right about that, but it still don't explain all the small strings on the heap. – iCediCe Aug 10 '15 at 13:59
  • @HansPassant by the way, the sting is just the key for the cache entry, it's userobjects that are cached. I believe that the cache is only emptied at midnight (when the pool recycles) so they would of cause survice into gen2. What would be a better approach for this? – iCediCe Aug 10 '15 at 14:02

1 Answers1

0

Maybe there is a second generation object that references those strings, the one that stores the return values of this method in a local field/variable on the stack?

The Gen 0 object will NOT be collected in Gen 0 collection if it is referenced and it will be promoted. If you create short living objects, that even for a very short period of time are referenced by the Gen 2 objects, that are immediately promoted during the assignment itself.

In short, I would do the following steps:

in windbg, run !dumpheap -type "System.String" -live

the -live switch will filter the objects that are referenced.

Pick a few objects of the fixed size that you are talking about, and call !gcroot [objAddr] where [objAddr] is the address of the String object. You will most likely find the object that temporarily holds the short living strings.

Stas Sh
  • 656
  • 4
  • 8