Recreational Debugging

Thursday, March 30, 2006

Eran Sandler runs a great ”Advanced .NET Debugging Blog”. In his recent post “Ambiguous match found in a Web Control - a Possible Bug”, Eran debugs the ASP.NET compiler to find the cause of an error message.

Eran could have fixed the ambiguous match error by changing some code and moving on with life, but it’s hard to pass up a good mystery. It’s fun to figure out why someone else’s code makes our code behave the way it does.

Here is a recent mystery I ran across: why does the following code invoke my workflow’s constructor twice?

WorkflowRuntime runtime = new WorkflowRuntime();
// ...
WorkflowInstance instance;
instance = runtime.CreateWorkflow(typeof(MyWorkflow));

The obvious first step is to drop a breakpoint in the constructor of MyWorkflow and look at the call stack (Ctrl+Alt+C).

console2.exe!PureCode.MyWorkflow.MyWorkflow() Line 12   
[External Code]    
console2.exe!chapter2_Host.Program.Main() Line 21 + 0x5 bytes

Unfortunately, [External Code] doesn’t tell us anything about where these calls are coming from. This is common when reflection is involved, like when using Activator.CreateInstance.

There are several viable approaches to unravel the mystery, but let’s try the SOS approach. First, we “enable unmanaged code debugging” in the project Debug properties, and then rerun the test harness. When execution stops on the breakpoint in the constructor, switch to the Immediate Window (Ctrl+Alt+I). Now we can load SOS, and look at the call stack with !clrstack.

.load sos
extension C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\sos.dll loaded
!clrstack
PDB symbol for mscorwks.dll not loaded
OS Thread Id: 0x570 (1392)

PureCode.MyWorkflow..ctor()
[GCFrame: 0012ef5c] 
[GCFrame: 0012f040] 
[HelperMethodFrame_2OBJ: 0012f05c] System.RuntimeTypeHandle.CreateInstance(...)
System.RuntimeType.CreateInstanceSlow(...)
System.RuntimeType.CreateInstanceImpl(...)
System.Activator.CreateInstance(...)
System.Workflow.Runtime.WorkflowDefinitionDispenser.GetRootActivity(...)
System.Workflow.Runtime.WorkflowRuntime.InitializeExecutor(...)
System.Workflow.Runtime.WorkflowRuntime.Load(...)
System.Workflow.Runtime.WorkflowRuntime.GetWorkflowExecutor(...)
System.Workflow.Runtime.WorkflowRuntime.InternalCreateWorkflow(...)
System.Workflow.Runtime.WorkflowRuntime.CreateWorkflow(...)
console2.Program.Main()

The superior stack trace produced by SOS reveals the workflow is instantiated from a method by the name of GetRootActivity. The second time the breakpoints is hit, !clrstack reveals InitializeExecutor as the method calling CreateInstance.

Armed with this bit of knowledge, it’s easy to use Reflector to see what is happening. The very first time the workflow runtime instantiates any given workflow Type, it creates the workflow twice. The runtime passes the first instance through a validation method to ensure the workflow is properly assembled (each activity in a workflow can define custom validations to ensure a proper configuration). The runtime tucks the validated object into a cache, so the runtime will know this workflow Type is “valid” for the duration of the AppDomain. After the first instantiation then, it can skip this validation step. The runtime only creates two instances the first time it sees a given Type.

Another curiosity solved.

All My Pluralsight Courses

OdeToCode by K. Scott Allen