Get GC Information in Silverlight


I had earlier written a post on getting GC information on Silverlight using ETW. With that we would have to write code to parse the ETW csv file.  In this post I am going to be using Perfmonitor to do this. This tools uses the same ETW under covers, but it does all the plumbing and gives a nice report , which is much easier to read.  Here are the reports

To demonstrate this I used the bing’s world leader search page and here is the url

http://www.bing.com/visualsearch?q=World+leaders&g=world_leaders&FORM=Z9GE74#

Steps to get the GC information are

  1. Start a cmd or powershell  as admin , this required to collect ETW tracing
  2. Browse the above mentioned webpage using IE
  3. Issue the command “PerfMonitor.exe /process:4180 start” where 4180 is the internet explorer’s process id
  4. Do the necessary actions
  5. Then issue “PerfMonitor.exe stop”
  6. The command to get the report “PerfMonitor.exe GCTime”. This will generate a report and open it in the browser

Perfmonitor is like xperf for managed code. This is non-intrusive and can collect some valuable information in production. This is an xcopy tool and does not need an install.

Get GC Information in Silverlight using ETW


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

image

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.

Undocumented Silverlight Feature – ETW Tracing


Event Tracing for Windows is tracing mechanism built into windows kernel. It is like log file for windows, but way cool and can log thousands events per second, with very less CPU utilization. From windows vista onwards, we can have windows ETW combined with our application tracing. It would be one trace file which would contain information about windows as well as our application, so it is easy to diagnose and figure what is happening in the OS combined with our application. Today I am not going be discussing about how to do this. I will write about in another post.  This post is going to be about how to have ETW tracing from Silverlight, which is not documented. I am using Silverlight 4.0 and I haven’t checked in another vesion.

I was looking to in to coreclr.dll inside the Windbg. FYI coreclr.dll is the runtime for Silverlight. And I happened to notice ETW. I used the command


x coreclr!etw*

0:026> x coreclr!etw*

6574af13 coreclr!ETW::MethodLog::MethodJitting = <no type information>

657434e5 coreclr!ETW::MethodLog::MethodJitted = <no type information>

6588810e coreclr!ETW::LoaderLog::CollectibleLoaderAllocatorUnload = <no type information>

65886240 coreclr!ETW::MethodLog::SendHelperEvent = <no type information>

6588327f coreclr!ETW::SamplingLog::SaveCurrentStack = <no type information>

6588752d coreclr!ETW::EnumerationLog::StartRundown = <no type information>

65887f30 coreclr!EtwCallback = <no type information>

65886e10 coreclr!ETW::EnumerationLog::IterateAssembly = <no type information>

6578ad0c coreclr!ETW::MethodLog::MethodRestored = <no type information>

65886450 coreclr!ETW::MethodLog::StubInitialized = <no type information>

65886729 coreclr!ETW::LoaderLog::SendModuleEvent = <no type information>

65884d0a coreclr!ETW::EnumerationLog::SendThreadRundownEvent = <no type information>

65884960 coreclr!ETW::LoaderLog::SendDomainEvent = <no type information>

65737ac1 coreclr!ETW::ExceptionLog::ExceptionThrown = <no type information>

658862e6 coreclr!ETW::MethodLog::SendEventsForNgenMethods = <no type information>

658837b0 coreclr!etwStackSupportedEvents = <no type information>

65887a60 coreclr!ETW::EnumerationLog::EndRundown = <no type information>

657a7b57 coreclr!ETW::MethodLog::StubsInitialized = <no type information>

657bb514 coreclr!ETW::CEtwTracer::Register = <no type information>

6588363e coreclr!EtwCallout = <no type information>

656de72b coreclr!ETWTraceStartup::ETWTraceStartup = <no type information>

658865c2 coreclr!ETW::MethodLog::DynamicMethodDestroyed = <no type information>

658853e8 coreclr!ETW::MethodLog::SendMethodEvent = <no type information>

65808659 coreclr!ETW::EnumerationLog::ProcessShutdown = <no type information>

657a67b0 coreclr!ETW::InfoLog::RuntimeInformation = <no type information>

65884e23 coreclr!ETW::LoaderLog::SendAssemblyEvent = <no type information>

65885198 coreclr!ETW::MethodLog::SendMethodJitStartEvent = <no type information>

658872ff coreclr!ETW::EnumerationLog::IterateCollectibleLoaderAllocator = <no type information>

658831d5 coreclr!ETW::SamplingLog::Append = <no type information>

6588840d coreclr!ETW::LoaderLog::ModuleLoad = <no type information>

656de705 coreclr!ETWTraceStartup::StartupTraceEvent = <no type information>

6588744b coreclr!ETW::EnumerationLog::EnumerationHelper = <no type information>

656fa2f8 coreclr!ETW::MethodLog::MethodTableRestored = <no type information>

65886f78 coreclr!ETW::EnumerationLog::IterateModule = <no type information>

656d11a4 coreclr!ETW::SecurityLog::StrongNameVerificationStart = <no type information>

658847f3 coreclr!ETW::GCLog::GCSettingsEvent = <no type information>

So this is cool we can get ETW tracing from Silverlight regarding loader, GC, threading, ThreadPool. But one thing I couldn’t find was a “.man” file like “CLR-ETW.man” for CLR 4.0. This was disappointing. The next thing to do was fired up .NET 4.0, attached to the debugger and issues the command x clr!ETW*.And it was same as the coreclr.dll output above.So the API’s being the same I guessed I could use the clr-etw.man for tracing Silverlight. Then the next thing to do is try tracing Silverlight using CLR-ETW.man. FYI I am using Windows 7 and this will work only from Windows Vista onwards. Make sure the CLR-ETW is registered. To register issue the command (clr-etw.man would be .NET 4.0 directory)


wevtutil im CLR-ETW.man

And to check if the provider is installed issue the command


xperf -providers I | Findstr ".NET"

And the output should be something like this

C:\>xperf -providers I | Findstr “.NET”

a669021c-c450-4609-a035-5af59af4df18     : Microsoft-Windows-DotNETRuntimeRundown

aff081fe-0247-4275-9c4e-021f3dc1da35      : ASP.NET Events

e13c0d23-ccbc-4e12-931b-d9cc2eee27e4    : .NETCommon Language Runtime

e13c0d23-ccbc-4e12-931b-d9cc2eee27e4    : Microsoft-Windows-DotNETRuntime

Try and close all .NET applications like VS2010, so that you don’t get traces from VS2010. From the command line issue the command


xperf -start usersession -on ".NET Common Language Runtime" -f usersession.etl

Start IE and browse a Silverlight site and then stop the trace


xperf -stop usersession

And to view the output of the etl file, issue the command


xperf usersession.etl

There we go now, we are able to see coreclr ETW tracing. From the above picture we can see information like assembly load, module load.  This can be used for GC, Exception, threading etc. So the next time someone tells the Silverlight site is slow on their box, you can ask them to run an etw trace and you would be able to see what is happening on their system.

Piracy in .NET /Silverlight Code – Part 1 – Even when the code is obfuscated


This is going to be a series of posts where I am going to demonstrating how someone with little advanced knowledge in .NET can hack in to the code, and circumventing licensing logic. I know there are other ways to prevent this ,which I am not going to be discussing about.

The usual assumption is that, if the code is obfuscated and signed , then it is close to impossible for someone to hack in to the code because the method names and variables are jumbled up, which would prevent someone from figuring what is happening.

In this post I am going to demonstrate a simple application which would prevent the user from updating the DataGrid because the user had downloaded only a trial version of the software. The software was supposed to disable grid and prevent the consumer from adding or updating the existing data, in a trial version. This was customer case, whom I helped in figuring out the vulnerability.

Here is the list of things the software did to prevent users from not accessing features that they were not entitled to

  1. Obfuscated the code, that prevented the code from being disassembled.
  2. The code that validated the consumers role either paid / trial alone was maintained in a separate assembly .So that for trial consumer’s, assembly version always returned false, for key features and for the paid subscribers got the assembly version that would return true. The organization assumption was ,by not even having the assembly ,trial users would never be able to circumvent the licensing logic. The customer could not maintain two versions of entire software, one for the trial another one paid because of the cost involved in maintenance and that’s the driving factor behind having a separate assembly.
  3. The code was signed and this prevented the users from hacking into the code and changing the code.

So here is code for figuring out the user role

public interface ICustomer{
bool HasAccess();}

And the trial assembly version code for figuring the role had

public class TrialCustomer : ICustomer {
public bool HasAccess() {
return false;
}
}

And here is the code that actually use the above code

private void Button1Click(object sender, EventArgs e)
{
if (!this.customer.HasAccess()) {
MessageBox.Show("Available only for paid customer");
}
else {
this.dataGridView1.Enabled = true;
}
}

So the idea behind this was, the trial version user would always get false as response, and would never be able to hack, because consumer does not even have library that would return true.

So I was asked to check for vulnerabilities. The first step was to disassemble the code using reflector and you can imagine the code had all weird names because of obfuscation.

The next step was to run the application and check when I get a dialog box for “Available only for paid customer”. The reason behind this was to get a callstack ,because all the methods names are jumbled and I didn’t know where to start.

When the messagebox popped up I attached the application to windbg and here is callstack

0:000> !clrstack

OS Thread Id: 0×4850 (0)

Child SP IP       Call Site

004ce758 752b438d [InlinedCallFrame: 004ce758]

004ce754 636308ec DomainBoundILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef, System.String, System.String, Int32)

004ce758 636f4a53 [InlinedCallFrame: 004ce758] System.Windows.Forms.SafeNativeMethods.MessageBox(System.Runtime.InteropServices.HandleRef, System.String, System.String, Int32)

004ce7ac 636f4a53 System.Windows.Forms.MessageBox.ShowCore(System.Windows.Forms.IWin32Window, System.String, System.String, System.Windows.Forms.MessageBoxButtons, System.Windows.Forms.MessageBoxIcon, System.Windows.Forms.MessageBoxDefaultButton, System.Windows.Forms.MessageBoxOptions, Boolean)

004ce7b0 001b0513 [InlinedCallFrame: 004ce7b0]

004ce84c 001b0513 c.a(System.Object, System.EventArgs)

004ce85c 630bfd6c System.Windows.Forms.Control.OnClick(System.EventArgs)

004ce874 630beb1e System.Windows.Forms.Button.OnClick(System.EventArgs)

004ce88c 636574b8 System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)

004ce8a8 63629639 System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)

004ce93c 639d1a87 System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)

004ce940 639f141d [InlinedCallFrame: 004ce940]

004ce994 639f141d System.Windows.Forms.ButtonBase.WndProc(System.Windows.Forms.Message ByRef)

004ce9d8 6312f8e0 System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)

004ce9e4 630ce493 System.Windows.Forms.Control+ControlNativeWindow.OnMessage(System.Windows.Forms.Message ByRef)

004ce9ec 630ce411 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)

004cea00 630ce356 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)

004ceba4 007a09e5 [InlinedCallFrame: 004ceba4]

004ceba0 631347dc DomainBoundILStubClass.IL_STUB_PInvoke(MSG ByRef)

004ceba4 630de59f [InlinedCallFrame: 004ceba4] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)

004cebe8 630de59f System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(IntPtr, Int32, Int32)

004cebec 630de1cc [InlinedCallFrame: 004cebec]

004cec84 630de1cc System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)

004cecdc 630de021 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)

004ced0c 630c5ecd System.Windows.Forms.Application.Run(System.Windows.Forms.Form)

004ced20 001b009a e.a()

004cef58 6d1d213b [GCFrame: 004cef58]

Notice that there is a method c.a(System.Object, System.EventArgs) on the top of stack the before the framework code. This was my starting point, and I looked up for it in the reflector

private void a(object A_0, EventArgs A_1)
{
if (!this.d.a())
{
MessageBox.Show("Available only for paid customer");
}
else
{
this.b.Enabled = true;
}
}

So my next step was to disassemble the call to “this.d.a()” and here is output from reflector

public class d : b
{
// Methods
public bool a()
{
return false;
}
}

And I was hoping there would be a class variable that I could update inside the debugger to activate the feature.  Like I mentioned I before ,I couldn’t update the assembly using ILASM or anything, because the assemblies were signed and there wasn’t any class variable to update. This assembly was for the trial version consumers which were supposed to always return false.

But there was one trick that I had. I could update the register on the function return, So what I mean is, when the function “a” is invoked by the button click to validate the consumer , I would update the return register  from false to true. By doing this my grid would be enabled and I circumvent the logic with the existing constraints.

So here are the steps to do it

  • So I looked for the type “d”  !dumpheap -type d, remember the TrialCustomer class  was the renamed  to d by obfuscator .
  • Go the method table as 00146b9c from the above command , using  the method table  I had to get the entry address for the function public bool a() because the buttonclick  was invoking the function.
  • I used the command  !dumpmt -md 00146b9c   to get the entry address for   d.a()  and here was the entry address 001b0540  .

0:005> !dumpmt -md 00146b9c

EEClass:      0020054c

Module:       00142e9c

Name:         d

mdToken:      02000009

File:         C:\Users\naveen\Documents\Visual Studio 2010\Projects\SecureApplication\bin\Debug\Dotfuscated\SecureApplication.exe

BaseSize:        0xc

ComponentSize:   0×0

Slots in VTable: 6

Number of IFaces in IFaceMap: 1

————————————–

MethodDesc Table

Entry MethodDesc      JIT Name

649f5b34   64795750   PreJIT System.Object.ToString()

649c8be0   64795758   PreJIT System.Object.Equals(System.Object)

649c8af0   64795778   PreJIT System.Object.GetHashCode()

649e8aa0   6479578c   PreJIT System.Object.Finalize()

001b0540   00146b8c      JIT d.a()

0014c085   00146b94     NONE d..ctor()

  • The idea behind getting the address was to set a break-point on 001b0540  . I used the command bp 001b0540 . So when the break-point hits I would create another break-point for the function return, which  is stored in the register @esp  bp poi(@esp). So what bp poi(@esp) essentially means is,   create a break-point on the return of function  , it is almost like having a break-point on the last line inside a function within VS.NET.
  • So when the break-point hits for the function return ,the return value is stored in the @eax register and here is the output

0:000> g

Breakpoint 1 hit

eax=00000000 ebx=0230e6f8 ecx=0230cfcc edx=02328884 esi=0230ce7c edi=02328884

eip=001b04f2 esp=004ce8a0 ebp=004ce8a4 iopl=0         nv up ei pl zr na pe nc

cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246

001b04f2 85c0            test    eax,eax

Now the trick is to update the @eax register from 00000000 to 00000001, by doing this we are changing the value from false to true, using the command  “r eax=00000001” and here is the output after updating the register

0:000> r

eax=00000001 ebx=0230e6f8 ecx=0230cfcc edx=02328884 esi=0230ce7c edi=02328884

eip=001b04f2 esp=004ce8a0 ebp=004ce8a4 iopl=0         nv up ei pl zr na pe nc

cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246

001b04f2 85c0            test    eax,eax

Now we have managed to update return of the function, which in turn has let us update the grid ,which was supposed to be available only to the paid customers.

In the forth coming posts I will continue to post of few more things that I figured out.

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: