Naveen's Blog

The coreclr.dll (Silverlight stripped down clr)  is a black box with respect to diagnostics information, until we had ETW. The only way was to get internal diagnostics information was using Windbg. But the idea is to get non-invasive diagnostic information. One of the most common performance issue in managed code, is the Garbage Collector. Either the application could be running out of memory, the percentage time spent on GC could be high and to address these GC performance issues in the desktop CLR, we would usually trouble shoot by observing at the performance counters, but this is not available in Silverlight. With the RIA , lot more work is done on the client and having  ETW/Xperf in our toolbox will certainly help us.

The coreclr.dll as well as the clr.dll provides ETW information, So what ever I am mentioning today is applicable to both Silverlight and the .NET framework 4.0. I am going to be profiling http://discoverbingmaps.com. FYI in this post I am going to be focusing only on the GC when collecting ETW traces.

Here is my original post on how to use ETW along with Silverlight. I am using xperf because I am running this out of windows 7. If you are using Windows XP then ,you could use Logman to record ETW traces.

Whenever I am troubleshooting perf issue I usually look for this

And in Silverlight we would have to get it from ETW. Here is the command

xperf -start clr -on Microsoft-Windows-DotNETRuntimeRundown:0x00000001:0x4 –f “clr GC.etl”

In the above command we are instructing xperf to start monitoring using the “clr” on the provider “Microsoft-Windows-DotNETRuntimeRundown”. The keyword within the provider which we want to log is “0×00000001” (which is for getting GC information) and “0×4” is the level of tracing which is Informational.

After starting the trace, I browsed the bing maps and then stopped the tracing and converted it to csv file

Xperf –stop clr
xperf  -i "CLR GC.etl" -o CLRGC.csv

Sample output of the HeapStats from the csv file

Microsoft-Windows-DotNETRuntime/GC /HeapStats,132775836,"Unknown" (5028),4424,0,0x0000000000a64d7c, 0x000000000000002c,0x0000000000000038,0x0000000000000024, 0x0000000002fca294 , 0x0000000002fc6048, 0x0000000003248478, 0x0000000001a07310, 0x0000000000000000,0,0,0,0,77

Sample output of GC Start / Stop

Microsoft-Windows-DotNETRuntime/GC /Start,6337636, "Unknown" (5028),4424,0,22,0,    0,    0,    77
Microsoft-Windows-DotNETRuntime/GC /Stop,     6342813,"Unknown" (5028),    4424,    0,    22,    0,    77

And here is the GC stats from the csv file after parsing it

Number of Gen 0:	 21
Number of Gen 1:	 26
Number of Gen 2:	 33
Collection Reason Small Object :	 21
Collection Reason Induced :	 14
Collection Reason LOH :	 1
Collection Reason Out Of Space (Small Objects) :	 3
Total Collections: 	  101
Total Time spent on GC: 	4087711
Generation Size 0:	10898812
Total Promoted Size 0:	44
Generation Size 2:	50111124
Total Promoted Size 2:	50094152
Generation Size 3:	52724856
Total Promoted Size 3:	27292432
Finalization Promoted Size 3:	0
Finalization Promoted count:	 0
Pinned object count:	 0
Sink block count:	 0
GC handle count:	 0

To get this ,I hacked a simple C# code to get it from csv file. This is sample code and by no means clean / perfect.

public static int Dec(string hex)
 {
 var x1 = hex.Remove(0,3);
 return int.Parse(x1,System.Globalization.NumberStyles.AllowHexSpecifier);
 }
 void Main()
{
 var map = new Dictionary<int,string>() { {0,"Small Object "},{1,"Induced "},{2,"Low Memory "},{3,"Empty "},{4,"LOH "},{5, "Out Of Space (Small Objects) "},{6,"Out of space LOH "} };

 var gclines = from line in File.ReadAllLines(@"C:\temp\clrgc.csv")
 where line.Contains("Microsoft-Windows-DotNETRuntime/GC /Start") ||
 line.Contains("Microsoft-Windows-DotNETRuntime/GC /Stop")
 select line;

 var heapStats = (from line in File.ReadAllLines(@"C:\temp\clrgc.csv")
 where line.Contains("Microsoft-Windows-DotNETRuntime/GC /HeapStats")
 select line).Last();

 var GCInfo = ((from col in gclines
 let cols = col.Split(new char[] {','})
 select   new {Name = cols[0],Time = cols[1], Count= cols[9], Depth = cols[10],Reason = cols[11]}));

 var totalCollections = GCInfo.ToList().Skip(2).OrderByDescending (g => Convert.ToInt32(g.Count)).ElementAt(1).Count;

 var collectioncount = (from y in GCInfo.Skip(2)
 group y by y.Depth into g
 select new {Gen = g.Key, Count = (g.Count()) /2});

 var collectionReasoncount = (from y in GCInfo.Skip(2)
 where y.Name.Contains("Microsoft-Windows-DotNETRuntime/GC /Start")
 group y by y.Reason into g
 select new {Reason = map[Convert.ToInt32(g.Key)], Count = (g.Count()) /2});

 var totalTimeSpentONGC = (from y in GCInfo.Skip(2)
 group y by y.Name into g
 select g.Select(g1 => Convert.ToInt32(g1.Time)));

 var start = totalTimeSpentONGC.First();
 var end = totalTimeSpentONGC.ElementAt(1);

 var timespentOnGC = start.Zip(end,(x,y) => y-x).Aggregate(0,(a,b) => a +b);

 collectioncount.ToList().ForEach(x => Console.WriteLine("Number of Gen"+x.Gen +":\t " + x.Count) );
 collectionReasoncount.ToList().ForEach(x => Console.WriteLine("Collection Reason " +x.Reason +":\t " + x.Count) );
 Console.WriteLine("Total Collections: \t "+ totalCollections );
 Console.WriteLine("Total Time spent on GC: \t" + timespentOnGC);
 var stats = heapStats.Split(new [] {','});
 Console.WriteLine("Generation Size 0:\t" +Dec(stats.ElementAt(9)));
 Console.WriteLine("Total Promoted Size 0:\t" +Dec(stats.ElementAt(10)));
 Console.WriteLine("Generation Size 2:\t" +Dec(stats.ElementAt(13)));
 Console.WriteLine("Total Promoted Size 2:\t" +Dec(stats.ElementAt(14)));
 Console.WriteLine("Generation Size 3:\t" +Dec(stats.ElementAt(15)));
 Console.WriteLine("Total Promoted Size 3:\t" +Dec(stats.ElementAt(16)));
 Console.WriteLine("Finalization Promoted Size 3:\t" +Dec(stats.ElementAt(17)));
 Console.WriteLine("Finalization Promoted count:\t" +stats.ElementAt(18));
 Console.WriteLine("Pinned object count:\t" +stats.ElementAt(19));
 Console.WriteLine("Sink block count:\t" +stats.ElementAt(20));
 Console.WriteLine("GC handle count:\t" +stats.ElementAt(21));
}

This is just a sample of what can be done with ETW and CLR. There are more cool things to come.