Ingo Rammer's Weblog

Slides, Demos and Notes for TechDays Ghent and DevWeek London

Ingo — Sun, 16 Mar 2008 18:10:00 GMT

Thanks for attending one of my sessions at the recent TechDays in Ghent or at DevWeek in London. As announced during the sessions, I have uploaded all materials and you can access them at the following locations:

Slides, Samples and Notes for DevWeek London (Debugging) - ZIP, 1.10 MB
Slides and Samples for TechDays in Ghent (WCF/WF Integration and Debugging) - ZIP, 1.80 MB

Slides and Demos for Prio Conference

Ingo — Thu, 15 Nov 2007 14:33:00 GMT

I've just uploaded the slides and demos for my debugging talks at Prio Conference. (Most of the materials will be in German).

Download

Notes for my TechEd Europe Talk - Hardcore Production Debugging

Ingo — Sat, 10 Nov 2007 08:32:00 GMT

As announced during my talk, I've uploaded my notes and samples for the session on production debugging. You can download them here:

Demo: ReallyBuggyApplication.zip (122 kb)
Notes: DebuggingNotes.txt (2kb)

Thanks for being there! I hope that you've enjoyed the session.

Dominick Baier joins thinktecture

Ingo — Mon, 12 Feb 2007 15:54:00 GMT

Well ... it's been inofficially known for quite a while, but today I'm proud to finally publicly annouce that .NET security wizard Dominick Baier has joined thinktecture as a consultant. I think that this is especially great as his in-depth security knowledge and experience (before going to .NET he used to work as a network penetration tester and a ISO certified security auditor) is really adding a lot of value to our combined knowledge. (And most importantly ... he's just a great guy to work with ...)

Dominick is also the one wrote one of the only .NET books I've read cover-to-cover in the recent months because it contained so much valueable content: Developing More Secure ASP.NET Applications.

thinktecture @ TechEd Europe Developers

Ingo — Fri, 03 Nov 2006 12:08:00 GMT

It's that time of the year again and in a few days, the European thinktects will get together at Microsoft's biggest gathering of developers in Europe. This time, we have a pretty intense schedule:

Monday
PRE008, 12:00 - 19:00, Ingo Rammer and Christian Weyer, Windows Workflow Foundation (WF) - Free Workflow Support for your Applications

Wednesday
DEV001, 13:30 - 14:45, Neno Loje, DEMO: Adopting ClickOnce for Real World Applications

Thursday
DEVWD15, 09:00 - 10:15, Ingo Rammer, Hardcore .NET Production Debugging
DEVWD17, 09:00 - 10:15, Neno Loje, Team System Adoption Best Practices
DEVWD15, 13:30 - 14:45, Ingo Rammer, Hardcore .NET Production Debugging (repeat)
DEVWD17, 15:45 - 17:00, Neno Loje, Team System Adoption Best Practices (repeat)
ARC309, 17:30 - 18:45, Dominick Baier, Security is a Feature - Best Practices for Designing Secure Distributed .NET Applications

Friday
DEV403, 09:00 - 10:15, Ingo Rammer, Optimizing Performance and Scalability of Distributed .NET Applications
DEV004, 13:30 - 14:45, Christian Weyer, DEMO: Technology in Action! Building a Distributed Solution with .NET Framework 3.0

I'm really looking forward to meeting you in Barcelona!

Update: Slides, samples and notes are online at http://www.thinktecture.com/Conferences/slides/TechEd2006/default.html.

Slides and Demos for the MSDN Event in Brussels

Ingo — Tue, 26 Sep 2006 06:37:00 GMT

As announced during the event, I have uploaded my slides and demos from yesterday's MSDN Event in Brussels to http://www.thinktecture.com/Conferences/slides/MsdnBrussels. Enjoy!

Off to Basta!2006

Ingo — Mon, 18 Sep 2006 12:07:00 GMT

In a few hours I'm off to Basta!2006. I'm really looking forward as this year thinktecture has a massive presence - even running in some parallel slots - at this conference. It's also the first time that the four of us in Europe meet in the current line-up as Neno Loje joined a few weeks ago to add his great VS Team System experience to our team.

Sept 18: Neno Loje - Full Day Tutorial on Team Development with Visual Studio 2005 Team System
Sept 19

10:15-11:30 - Neno Loje - Visual Studio 2005 Team System
10:15-11:30 - Ingo Rammer - Hardcore Production Debugging
14:15-15:30 - Christian Nagel - C++/CLI
17:15-18:35 - Christian Nagel - System.Transactions

Sept 20

10:15-11:30 - Christian Weyer - Windows Communication Foundation: Think First, Speak Later
11:45-13:00 - Christian Weyer - Windows Workflow Foundation: Because Workflow is Everywhere
11:45-13:00 - Ingo Rammer - The Smart Client Software Factory

Sept 21: Christian Weyer, Ingo Rammer - Full Day Tutorial on Windows Workflow Foundation

It's going to be fun - see you in a few hours.

Defining KnownTypes in a configuration file

Ingo — Wed, 06 Sep 2006 17:03:00 GMT

WCF's serialization of data contracts supports the transmission of derived types which have not been available when the original application (or just contract) has been built. In the following example, ApplicationExtensionObject is just a placeholder instead of which a derived class should be transferred at runtime.

[DataContract]
public class Customer
{
  [DataMember]
  public string Firstname;
  [DataMember]
  public string Lastname;
  [DataMember]
  public Address DefaultDeliveryAddress;
  [DataMember]
  public Address DefaultBillingAddress;

  [DataMember]
  public ApplicationExtensionObject Extension;
}

[DataContract]
public class ApplicationExtensionObject
{
}

You would normally accomplish this using the [KnownType] attribute on the field Extension. But what if you can't do this as the type is not yet known at compile time? Well, for one thing you could use [KnownType(methodName)] to define a method which returns an array of Types at runtime. Another alternative is to use the section to define the mapping between declared types and known subtypes.

In the following snippet, the class ProjectSpecificExtension.CustomerExtension is defined as a valid known subtype of ApplicationExtensionObject for the serializer.

<configuration >
  <system.runtime.serialization>
    <dataContractSerializer>
      <declaredTypes>
        <add type="Shared.ApplicationExtensionObject, Shared">
          <knownType type="ProjectSpecificExtension.CustomerExtension, ProjectSpecificExtension" />
        </add>
      </declaredTypes>
    </dataContractSerializer>
  </system.runtime.serialization>
  ...
</configuration>

Update: This has actually been documented and is a supported practice. I guess I just made it too much of a habit to look into Reflector instead of searching long enough in the docs ;-)

Start ServiceHosts for all configured Services

Ingo — Tue, 05 Sep 2006 12:47:00 GMT

Important Update: The originally presented code only works if the service is defined in the same assembly which hosts the service (because the name="" attribute in <service> may not contain the assembly name of the service). See at the end of the article for a slightly different version which works in all cases --- but which involves adding a second config file.

As WCF has reached RC1 stage, I find myself cleaning up a few bits of older WCF code. While playing around with it, I always found myself having to start more and more ServiceHosts for different configurations. The following snippet iterates over all <service> entries in configuration/system.serviceModel and opens a ServiceHost for each of them.

Update: Added code to close all services.

using System;
using System.Collections.Generic;
using System.Reflection;
using System.Configuration;
using System.ServiceModel.Configuration;
using System.ServiceModel;

public class ServiceHostGroup
{
    static List<ServiceHost> _hosts = new List<ServiceHost>();

    private static void OpenHost(Type t)
    {
        ServiceHost hst = new ServiceHost(t);
        hst.Open();
        _hosts.Add(hst);
    }

    public static void StartAllConfiguredServices()
    {
        Configuration conf =
          ConfigurationManager.OpenExeConfiguration(Assembly.GetEntryAssembly().Location);

        ServiceModelSectionGroup svcmod =
          (ServiceModelSectionGroup)conf.GetSectionGroup("system.serviceModel");
        foreach (ServiceElement el in svcmod.Services.Services)
        {
            Type svcType = Type.GetType(el.Name);
            if (svcType == null)
              throw new Exception("Invalid Service Type " + el.Name + " in configuration file.");
            OpenHost(svcType);
        }

    }

    public static void CloseAllServices()
    {
    foreach (ServiceHost hst in _hosts)
      {
        hst.Close();
      }
    }
}

As mentioned above, I have in the meantime learned (after long and hard fighting against the "this service has no non-metadata endpoints"-exception), that the name="" attribute in <service> must not contain an assembly name. I guess I have been too used to Remoting configuration files after all ;-). To still get dynamic service configuration without code changes, I've added a second configuration file called services.xml and changed the code for ServiceHostGroup to the following:

Services.XML:

<configuredServices>
<service type="ServiceImplementation.ArticleService, ServiceImplementation" />
</configuredServices>

ServiceHostBase.cs:

using System;
using System.Collections.Generic;
using System.Reflection;
using System.Configuration;
using System.ServiceModel.Configuration;
using System.ServiceModel;
using System.Xml;
using System.Xml.Serialization;
using System.IO;

public class ServiceHostGroup
{
static List<ServiceHost> _hosts = new List<ServiceHost>();

private static void OpenHost(Type t)
{
    ServiceHost hst = new ServiceHost(t);
    Type ty = hst.Description.ServiceType;
    hst.Open();
    _hosts.Add(hst);
}

public static void StartAllConfiguredServices()
{
    ConfiguredServices services = ConfiguredServices.LoadFromFile("services.xml");

    foreach (ConfiguredService svc in services.Services)
    {
      Type svcType = Type.GetType(svc.Type);
      if (svcType == null) throw new Exception("Invalid Service Type " + svc.Type + " in configuration file.");
      OpenHost(svcType);
    }
}

public static void CloseAllServices()
{
    foreach (ServiceHost hst in _hosts)
    {
      hst.Close();
    }
}
}

[XmlRoot("configuredServices")]
public class ConfiguredServices
{
public static ConfiguredServices LoadFromFile(string filename)
{
    if (!File.Exists(filename)) return new ConfiguredServices();

    XmlSerializer ser = new XmlSerializer(typeof(ConfiguredServices));
    using (FileStream fs = File.OpenRead(filename))
    {
      return (ConfiguredServices) ser.Deserialize(fs);
    }
}

[XmlElement("service", typeof(ConfiguredService))]
public List<ConfiguredService> Services = new List<ConfiguredService>();
}

public class ConfiguredService
{
[XmlAttribute("type")]
public string Type;
}

WCF server startup slow on W2K3 in VM

Ingo — Mon, 04 Sep 2006 19:20:00 GMT

Just a quick and unrelated tip: If you - like I'm doing it right now - run a WCF server in a Virtual Machine running W2K3 Server and your VM is supposed to be standalone and not part of domain you might experience a delay when a WCF server application is starting. When looking at the issue with Wireshark/Ethereal (yes, I do what I preach and a Network Sniffer really is one of the first things I use when I experience some kind of unexpected delay ;-)) I noticed that the machine is broadcasting eight Netbios name service queries on its internal subnet to find a domain controller. These queries time out after about eight seconds, but I really didn't want to wait that long.

I'm sure that there are dozens of ways around it, but I simply converted my standalone W2K3 VM to a standalone Domain Controller. Startup time decreased from 8 seconds to less than one second for each time I hit F5 in Visual Studio.

Coming to Brussels on September 25

Ingo — Tue, 15 Aug 2006 04:58:00 GMT

As David has already blogged, I will be back in Brussels on September 25. I think that's great as I really like the city and wasn't able to make it to the last DevDays there.

Microsoft is hosting (for free!) a full day on .NET Framework 3.0 in which Peter Himschoot will present on Windows Presentation Foundation and CardSpace, and I'll focus on Windows Communication Foundation and Workflow Foundation. It's going to be fun. (And: You can still vote for the session contents!)

Who is blocking that Mutex? - Fun with WinDbg, CDB and KD

Ingo — Sat, 05 Aug 2006 09:31:00 GMT

I'm currently toying with the idea of creating a small frontend to SOS.DLL (CDB/WinDbg) and KD. This frontend should simplify some production debugging tasks based on crash dumps. (In my prototype, I'm already happily clicking myself through managed code threads, callstacks, parameters, locals and browsing objects' contents just like in Visual Studio, but solely based on crash dumps.)

A lot of debugging work is in general based on identifying a set of rather common issues. But even if you are tracking down a very common issue, it's still a tough call to work through 25 managed code callstacks to find out - for example - why a certain thread might be blocking a number of other threads. This was the rationale behind some of the features I'm thinking about implementing in the debugging frontend tool: to simplify and automate some manual tasks. But this tool is not (yet) ready for writing about, so lets look at the manual process for finding out whos blocking your thread.

For the analysis of thread blocks based on WaitHandles, I've found two kinds of possible solutions: one which is not 100% deterministic but works on crash dumps (but only for named synchronization objects) and another one which is deterministic but only works on the live system with a kernel debugger. I'll show you both approaches in this post.

First Approach - User Mode only, but works on Dumps

Note: This approach is not deterministic and not accurate but based on the automated equivalent of trial and error in the form of !DumpStackObjects. It's essentially based on looking for WaitHandle references on a callstack and similar means to get the identifier of a named synchronization object. The only good news is that it works on dumps generated by ADPlus (and of course on live systems as well).

Ok. Let's get startet. Suppose you have a process in which several threads end up blocking others for periods longer than you would expect and you basically want to know which threads block on resources held by which other threads. You've created a -hang dump with ADPlus and are ready to examine the dump in WinDbg or CDB.

First, you will need to find out which threads are actually waiting for something. To do this, you first load SOS.DLL and then look at the states of your managed threads:

0:013> .loadby sos mscorwks     // load the extension sos.dll in directory of mscorwks
0:013> !threads                   // list all managed threads
ThreadCount: 12
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ   State     GC       Context       Domain   Count APT Exception
   0    1  b70 00180fd0   200a020 Enabled  00000000:00000000 0014c100     0 MTA
   2    2 1b54 00152480      b220 Enabled  00000000:00000000 0014c100     0 MTA (Finalizer)
   3    3 1ba0 0019a1c0   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   4    4 1f9c 0019c138   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   5    5  210 0019cd18   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   6    6 13e0 0019d8d0   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   7    7 17e0 0019e488   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   8    8 1204 0019f040   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   9    9 1ec0 0019fbf8      b020 Disabled 00000000:00000000 0014c100     0 MTA
  10    a 1a48 001a07b0      b020 Disabled 00000000:00000000 0014c100     0 MTA
  11    b 1558 001a1368   200b020 Enabled  00000000:00000000 0014c100     0 MTA
  12    c 1d88 001a1f20   200b020 Enabled  00000000:00000000 0014c100     0 MTA

The threads with state 200a020 are currently waiting. As this does not necessarily mean that they are waiting for a WaitHandle (they could also just have called Thread.Sleep()), you now also need to find out which of these blocked threads are actually blocking on a WaitHandle.

To do this, you will have to look at the top managed code stackframe in each of the blocked threads. (Please note: You have to specify the native thread ID for the next command. This ID is contained in the first column of !threads, and is not the CLR thread id contained in the second column!)

0:007> ~0e !clrstack            // list the managed call stack of thread 0 (CLR thread #1)
OS Thread Id: 0xb70 (0)
ESP       EIP
0012f420 7c90eb94 [HelperMethodFrame: 0012f420] System.Threading.Thread.SleepInternal(Int32)
0012f474 793d80f5 System.Threading.Thread.Sleep(Int32)
0012f478 00ca00fb ResourceLock.Program.Main(System.String[])
0012f69c 79e88f63 [GCFrame: 0012f69c]

As you can see in this first example, the specified thread does not block on a WaitHandle, so let's continue our search. (Note: instead of manually using ~<THREAD_NUMBER>e !clrstack for each thread, you could also call ~*e !clrstack, do dump the complete managed code callstacks for all threads.)

0:007> ~7e !clrstack           // list the managed call stack of thread 7 (also CLR thread #7)
OS Thread Id: 0x17e0 (7)
ESP       EIP
011cf588 7c90eb94 [HelperMethodFrame_1OBJ: 011cf588] System.Threading.WaitHandle.WaitOneNative(Microsoft.Win32.SafeHandles.SafeWaitHandle, U
Int32, Boolean, Boolean)
011cf634 793d424e System.Threading.WaitHandle.WaitOne(Int64, Boolean)
011cf64c 793d4193 System.Threading.WaitHandle.WaitOne(Int32, Boolean)
011cf65c 793d420e System.Threading.WaitHandle.WaitOne()
011cf660 00ca0250 ResourceLock.Program.ThreadProc()
011cf6b4 793d7a7b System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
011cf6bc 793683dd System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
011cf6d4 793d7b5c System.Threading.ThreadHelper.ThreadStart()
011cf8f8 79e88f63 [GCFrame: 011cf8f8]

Here, the top level call stack elements contain calls to WaitHandle.WaitOne() or WaitOneNative(). This thread is currently waiting for a synchronization object.

To retrieve details of the underlying sync object, you first have to look at the unmanaged callstack for the same thread. You will usually send a command like "kb 5" to the debugger after selecting the current thread with ~7 s.

0:007> ~7 s                   // select thread 7 if its not the current thread
eax=00000000 ebx=011cf350 ecx=79690098 edx=79690048 esi=00000000 edi=7ffde000
eip=7c90eb94 esp=011cf328 ebp=011cf3c4 iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023 ds=0023  es=0023  fs=003b  gs=0000             efl=00000202
ntdll!KiFastSystemCallRet:
7c90eb94 c3              ret
0:007> kb 5                   // print five stack frames
ChildEBP RetAddr  Args to Child
011cf324 7c90e9ab 7c8094f2 00000001 011cf350 ntdll!KiFastSystemCallRet
011cf328 7c8094f2 00000001 011cf350 00000000 ntdll!ZwWaitForMultipleObjects+0xc
011cf3c4 79f8ead4 00000001 011cf614 00000001 KERNEL32!WaitForMultipleObjectsEx+0x12c
011cf42c 79f17522 00000001 011cf614 00000001 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f
011cf44c 79f17493 00000001 011cf614 00000001 mscorwks!Thread::DoAppropriateAptStateWait+0x3c

Please note: This output is what youll receive if you have debug symbols configured correctly. While its definitely not as nice as the one with symbols, you can still get the same information (minus the method names) even if you do not have debug symbols installed:

0:007> kb 5                   // print five stack frames
ChildEBP RetAddr  Args to Child
WARNING: Stack unwind information not available. Following frames may be wrong.
011cf3c4 79f8ead4 00000001 011cf614 00000001 ntdll!KiFastSystemCallRet
011cf42c 79f17522 00000001 011cf614 00000001 mscorwks!StrongNameFreeBuffer+0x57fc
011cf44c 79f17493 00000001 011cf614 00000001 mscorwks!CreateAssemblyCache+0x9474
011cf4d0 79f1732f 00000001 011cf614 00000001 mscorwks!CreateAssemblyCache+0x93e5
011cf520 7a07b49c 00000001 011cf614 00000001 mscorwks!CreateAssemblyCache+0x9281

Here, I'll ignore the first three lines in any case, no matter if we have symbols or not. The next line is usually a call to WaitForMultipleObjectEx or a comparable function. This function is defined like this:

DWORD WaitForMultipleObjectsEx(
  DWORD nCount,
  const HANDLE* lpHandles,
  BOOL bWaitAll,
  DWORD dwMilliseconds,
  BOOL bAlertable
);

In the third, fourth and fifth field of the output of kb 5, we can get the first three arguments to the method. We therefore know that nCount = 1 and lpHandles = 011cf614. This means that the .NET Framework has passed an array of handles which contains 1 (nCount) entry and starts at the location 011cf614 (lpHandles) to WaitForMultipleObjectsEx.

You can then call "dd <address> L<number_of_handles>" (for example "dd 011cf614 L00000001") to the debugger to generate a memory dump to retrieve the list of handles.

0:007> dd 011cf614 L1     // dump 1 dword at location 011cf614
011cf614  00000684

In this command, the first field in each line contains the memory address and the subsequent fields (only one in our case) contain the handle to the object you are waiting for.

For each handle, you can then then call "!handle <handle> f", for example "handle 00000684 f" to retrieve handle information:

0:007> !handle 00000684 f            // dump detailed information (flags = f) for handle 684
Handle 684
  Type          Mutant
  Attributes    0
  GrantedAccess 0x1f0001:
         Delete,ReadControl,WriteDac,WriteOwner,Synch
         QueryState
  HandleCount   4
  PointerCount  8
  Name         \BaseNamedObjects\{1CA3A6E4-68E7-4847-9602-5669BC40D01E}
  Object Specific Information
    Mutex is Owned

In this case, you now know that the thread is waiting for a Mutex (Mutant is the kernel-level name for a Mutex) which has been named "{1CA3A6E4-68E7-4847-9602-5669BC40D01E}".

The next step is to find out who currently owns this mutex. This would be relatively straightforward in a live debug as we could use a kernel debugger to identify the owning thread (which I'll explain later). In a crash dump however, we are somewhat limited as we have to hunt for this information in a trial-and-error way. We are also limited to owner threads in the same process if the named mutex is owned by a thread in another process, we won't be able to get there with our single-process memory dump.

This trial-and-error information retrieval comes in the form of !DumpStackObjects (which can be abbreviated to !dso), an extension command which walks the stack of the selected thread and checks if each value it finds on the stack could be a managed object.

0:007> ~0e !dso                     // dump stack objects for thread #0
OS Thread Id: 0xb70 (0)
ESP/REG  Object   Name
0012f408 01273450 System.IO.StreamWriter
0012f428 01274768 System.Char[]
0012f478 01271b38 System.Object[]    (System.String[])
0012f534 01271b38 System.Object[]    (System.String[])
0012f6e0 01271b38 System.Object[]    (System.String[])
0012f708 01271b38 System.Object[]    (System.String[])

Theres not a lot going on in this thread. Certainly no Mutex here, let's go on:

0:007> ~4e !dso                     // dump stack objects for thread #4
OS Thread Id: 0x1f9c (4)
ESP/REG  Object   Name
00ecf748 01273b30 System.String    Thread 4 sleeping
00ecf770 01273450 System.IO.StreamWriter
00ecf790 01273b64 System.Char[]
00ecf804 01273a40 System.Threading.ThreadStart
00ecf808 01273a40 System.Threading.ThreadStart
00ecf80c 01273a94 System.Threading.ThreadHelper
00ecf814 01271db8 System.String    Thread
00ecf818 01273a94 System.Threading.ThreadHelper
00ecf81c 01271d98 System.Threading.ContextCallback
00ecf820 01273a94 System.Threading.ThreadHelper
00ecf82c 01273a94 System.Threading.ThreadHelper
00ecf834 01273ac8 System.Threading.ExecutionContext
00ecf844 01273ac8 System.Threading.ExecutionContext
00ecf848 01273a94 System.Threading.ThreadHelper
00ecf850 01273a94 System.Threading.ThreadHelper
00ecf914 01273aa8 System.Threading.ThreadStart
00ecfac0 01273aa8 System.Threading.ThreadStart
00ecfad0 01273aa8 System.Threading.ThreadStart

Thread #4 looks more interesting but contains no reference to any synchronization object, let's continue again:

0:007> ~3e !dso                     // dump stack objects for thread #3
OS Thread Id: 0x1ba0 (3)
ESP/REG  Object   Name
00daf7c8 012739d8 System.String    Thread 3 sleeping
00daf7f0 01273450 System.IO.StreamWriter
00daf810 01273a0c System.Char[]
00daf880 0127383c System.Threading.Mutex
00daf884 01271db8 System.String    Thread
00daf888 01271db8 System.String    Thread
00daf88c 01271db8 System.String    Thread
00daf898 01271cb8 System.Threading.ThreadHelper
00daf89c 01271d98 System.Threading.ContextCallback
00daf8a0 01271cb8 System.Threading.ThreadHelper
00daf8ac 01271cb8 System.Threading.ThreadHelper
00daf8b4 01271d2c System.Threading.ExecutionContext
00daf8c4 01271d2c System.Threading.ExecutionContext
00daf8c8 01271cb8 System.Threading.ThreadHelper
00daf8d0 01271cb8 System.Threading.ThreadHelper
00daf994 01271ccc System.Threading.ThreadStart
00dafb40 01271ccc System.Threading.ThreadStart
00dafb50 01271ccc System.Threading.ThreadStart

At first glance, thread #3 looks innocent too. Only when examining it more closely, you'll find a Mutex as the fourth stack object. (Of course, this is now total guesswork as we don't know if the thread ever really acquired the mutex or if it is just looking at it. The thread might also have already released the mutex as well but I don't know if we can find an answer to these questions without looking at kernel memory.)

First, lets look if the method acquires a mutex at all. To do this, we first need to find out the method which owns this section of the stack. To do this, we take the value of ESP for our Mutex (which is the address on the stack which references the mutex) which is 00daf880 in our case and compare it to the managed code stack dump of the same thread:

0:007> ~3 s                   // select thread #3
eax=7a38cf40 ebx=00000000 ecx=79ed75c0 edx=fbffffff esi=00000000 edi=00daf700
eip=7c90eb94 esp=00daf6d0 ebp=00daf728 iopl=0         nv up ei pl nz na pe nc
cs=001b  ss=0023 ds=0023  es=0023  fs=003b  gs=0000             efl=00000206
ntdll!KiFastSystemCallRet:
7c90eb94 c3              ret
0:003> !clrstack               // dump the managed code stack for this method
OS Thread Id: 0x1ba0 (3)
ESP       EIP
00daf808 7c90eb94 [HelperMethodFrame: 00daf808] System.Threading.Thread.SleepInternal(Int32)
00daf85c 793d80f5 System.Threading.Thread.Sleep(Int32)
00daf860 00ca02c3 ResourceLock.Program.ThreadProc()
00daf8b4 793d7a7b System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
00daf8bc 793683dd System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00daf8d4 793d7b5c System.Threading.ThreadHelper.ThreadStart()
00dafaf8 79e88f63 [GCFrame: 00dafaf8]

In this stack dump, you can see that the stack address of the reference to the mutex (00daf880) lies between the third and the fourth frame's ESP. You can deduce that the object is created in the third frame, in the method ResourceLock.Program.ThreadProc().

To verify this, you can have a look at the IL code of this method. First you need to convert the Instruction Pointer (IP) to a method description. The IP is 00ca02c3 according to the output of !clrstack (second field in the stack frame for ThreadProc()).

0:003> !IP2MD 00ca02c3        // convert an instruction pointer (IP) to a method description (MethodDesc)
MethodDesc: 00912ff8
Method Name: ResourceLock.Program.ThreadProc()
Class: 009112c4
MethodTable: 00913010
mdToken: 06000003
Module: 00912c14
IsJitted: yes
m_CodeOrIL: 00ca0188

The resulting MethodDesc is 00912ff8. You can use this a parameter to !DumpIL to retrieve the IL code of this method:

0:003> !dumpil 00912ff8        // get the IL code for a method
ilAddr = 004020b4
IL_0000: nop
IL_0001: call System.Threading.Thread::get_CurrentThread
  ...
IL_004a: newobj System.Threading.Mutex::.ctor
IL_004f: stloc.2
IL_0050: ldloc.2
IL_0051: callvirt System.Threading.WaitHandle::WaitOne

IL_0044 to IL_51 roughly translate to the following C# fragment:

Mutex mtx = new Mutex (...);
mtx.WaitOne();

So, yes, the method definitely acquires at least one mutex at one point. But to find out if the the Mutex we've found on the stack really references the same named synchronization object the other thread is blocking on, we need to examine it more closely. First, let's have a look at the contents of the mutex by using !DumpObj (which we abbreviate to !do).

0:003> !do 0127383c     // dump the mutex. Address is from ~3e !dso
Name: System.Threading.Mutex
MethodTable: 7910d018
EEClass: 7910cfa0
Size: 24(0x18) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
790f9c18  4000184       4        System.Object  0 instance 00000000 __identity
790fe160  40005a6        c        System.IntPtr  0 instance     1752 waitHandle
7910cf3c  40005a7        8 ...es.SafeWaitHandle  0 instance 012738d8 safeWaitHandle
79104f64  40005a8       10       System.Boolean  0 instance        1 hasThreadAffinity
790fe160  40005a9     984        System.IntPtr  0   shared   static InvalidHandle
    >> Domain:Value 0014c100:-1 <<
79104f64  40005ee      990       System.Boolean  0   shared   static dummyBool
    >> Domain:Value 0014c100:NotInit  <<
7910d018  40005ef      14c ...m.Threading.Mutex  0   shared   static s_ReservedMutex
    >> Domain:Value 0014c100:NotInit  <<

The second field is called waitHandle and contains the value 1752. This is the decimal handle to the underlying mutex. Lets convert this to hex (6d8) and have a look at the handle:

0:003> !handle 6d8 f          // look at handle 6d8 (decimal 1752)
Handle 6d8
  Type          Mutant
  Attributes    0
  GrantedAccess 0x1f0001:
         Delete,ReadControl,WriteDac,WriteOwner,Synch
         QueryState
  HandleCount   4
  PointerCount  8
  Name         \BaseNamedObjects\{1CA3A6E4-68E7-4847-9602-5669BC40D01E}
  Object Specific Information
    Mutex is Owned

As you can see, thread #3 acquired the mutex with the name {1CA3A6E4-68E7-4847-9602-5669BC40D01E} using wait handle 6d8, and this is the exact same named mutex which thread #7 is waiting for on wait handle 684. It seems that we got lucky this time and could find the mutex in our crash dump. Whats left as an exercise is to dump the !clrstack of thread #3 and examine the top stackframes using !IP2MD and !DumpIL to find out why the mutex has not been released in time.

The Deterministic Second Approach - or: Now give me my Kernel Debugger!

If someone would have told me just two years ago that I'd ever start a kernel debugger, I wouldn't have believed him: after all, I'm not writing device drivers and that's all you need KD.EXE for and it's quite difficult to setup kernel debugging in the first place, right? Well, turns out that neither is the case.

If you only want to examine kernel structures on your local machine, you can start a kernel debugger as easily as KD.EXE /KL (and it's part of the same Debugging Tools for Windows package which contains WinDbg and CDB). Theres no need to setup a second machine and connect the debugger to it or anything like this. The only really important part is that contrary to WinDbg and CDB you absolutely have to have debug symbols configured correctly for what we are doing now. Usually its enough to just create a directory like c:\symbols, set _NT_SYMBOL_PATH to the matching entry SRV*c:\symbols*http://msdl.microsoft.com/download/symbols and start KD. The necessary symbols will be downloaded automatically behind the scenes whenever they are needed for the first time. (Note that this also means that KD will block from time to time while it's downloading symbols on demand.)

C:\debug>set _NT_SYMBOL_PATH=SRV*C:\symbols*http://msdl.microsoft.com/download/symbols
 
C:\debug>kd /KL

Microsoft (R) Windows Debugger Version 6.6.0007.5
Copyright (c) Microsoft Corporation. All rights reserved.

Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE
Symbol search path is: SRV*C:\symbols*http://msdl.microsoft.com/download/symbols
Executable search path is:
*******************************************************************************
WARNING: Local kernel debugging requires booting with /debug to work optimally.
*******************************************************************************
Windows XP Kernel Version 2600 (Service Pack 2) UP Free x86 compatible
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 2600.xpsp_sp2_gdr.050301-1519
Kernel base = 0x804d7000 PsLoadedModuleList = 0x8055a420
Debug session time: Sat Aug  5 11:19:11.543 2006 (GMT+2)
System Uptime: 6 days 14:14:43.119
lkd>

Well, allright then. Let's start to hunt for the mutex. And don't forget: you can run WinDbg/CDB *and* KD at the same time to debug the user-mode and the kernel-mode parts side by side!

First, we need to get information about the process which we are debugging. The EXE in my example is called ResourceLock.exe, but you can use the !process command in KD to retrieve the necessary entry point for any process on your machine: (I'll use red color coding for KD commands and blue color coding for CDB commands)

lkd> !process 0 0 ResourceLock.exe         // retrieve information for all processes running ResourceLock.exe
PROCESS 8900e020  SessionId: 0 Cid: 1cd0    Peb: 7ffde000  ParentCid: 12a0
    DirBase: 0cb83000  ObjectTable: e72125c8  HandleCount: 122.
    Image: ResourceLock.exe

The !process command can also be used to retrieve additional information. It accepts two numeric parameters: the process address and a list of flags. If you specify the process address we've retrieved above (8900e020) and the value 2 for flags, you'll get detailed information about the individual threads and their synchronization objects:

Important: If you are running WinDbg/CDB and KD side-by-side for the same process, you must switch WinDbg/CDB in to run mode (F5 or g) to retrieve this information.

lkd> !process 8900e020 2            // retrieve thread info for process
PROCESS 8900e020  SessionId: 0 Cid: 1cd0    Peb: 7ffde000  ParentCid: 12a0
    DirBase: 0cb83000 ObjectTable: e72125c8  HandleCount: 122.
    Image: ResourceLock.exe
 
        THREAD 89285020  Cid 1cd0.0b70  Teb: 7ffdd000 Win32Thread: e52fe420 WAIT: (DelayExecution) UserMode Alertable
            89285110 NotificationTimer
 
        THREAD 8a02f280  Cid 1cd0.0268  Teb: 7ffdc000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Non-Alertable
            891da5f8 SynchronizationEvent
            8a13d6f8 SynchronizationEvent
            89d50020 SynchronizationEvent
 
        THREAD 88f9fd58  Cid 1cd0.1b54  Teb: 7ffdb000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Non-Alertable
            8a2fe310 NotificationEvent
            8974b6f0 SynchronizationEvent
 
        THREAD 89d86da8  Cid 1cd0.1ba0  Teb: 7ffda000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            89d86e98 NotificationTimer
 
        THREAD 8902e020  Cid 1cd0.1f9c  Teb: 7ffd9000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            8902e110 NotificationTimer
 
        THREAD 87b86020  Cid 1cd0.0210  Teb: 7ffd8000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            87b86110 NotificationTimer
 
        THREAD 8971b828  Cid 1cd0.13e0  Teb: 7ffd7000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            8971b918  NotificationTimer
 
        THREAD 87ba5020  Cid 1cd0.17e0  Teb: 7ffd6000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Alertable
            89d48fc0  Mutant - owning thread 89d86da8
 
        THREAD 88724da8  Cid 1cd0.1204  Teb: 7ffd5000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            88724e98 NotificationTimer
 
        THREAD 8869e548  Cid 1cd0.1ec0  Teb: 7ffd4000 Win32Thread: 00000000 READY
        THREAD 88e28020  Cid 1cd0.1a48  Teb: 7ffaf000 Win32Thread: 00000000 READY
        THREAD 88ab5020  Cid 1cd0.1558  Teb: 7ffae000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            88ab5110 NotificationTimer
 
        THREAD 88827360  Cid 1cd0.1d88  Teb: 7ffad000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Alertable
            89d48fc0  Mutant - owning thread 89d86da8

Fantastic, isn't it? Everything we've been looking for with trial-and-error analysis with WinDbg/CDB is contained in this single output.

But let's just look at the three important threads for this list (the two which have a Mutant in their list of kernel objects, and the thread which is specified as the owner for this mutant):

        THREAD 89d86da8  Cid 1cd0.1ba0  Teb: 7ffda000 Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            89d86e98 NotificationTimer

        THREAD 87ba5020  Cid 1cd0.17e0  Teb: 7ffd6000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Alertable
            89d48fc0  Mutant - owning thread 89d86da8

        THREAD 88827360  Cid 1cd0.1d88  Teb: 7ffad000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Alertable
            89d48fc0  Mutant - owning thread 89d86da8

WAIT: (DelayExecution) in the first line means that the thread is sleeping. The next line indicates the kernel object which the thread is waiting for. It is a NotificationTimer and its a safe bet to assume that this is the timer which has caused the DelayExecution in the first place. By the way: If you've forgotten to switch your user mode debugger into run mode - just like it happens to me all the time - your threads will be marked as WAIT: (Suspended) KernelMode Non-Alertable. In this case, just hit F5 or g in your user mode debugger and re-try the !process command.

The second and third thread in this list are both in WAIT: (UserRequest). The synchronization object is in both cases the Mutant which is currently owned by thread 89d86da8. This owner thread is the first thread in our list. To match this information back to our user-mode information, we need to look at the thread's Cid, which is 1cd0.1ba0 in our case. Of this Cid, the first part (1cd0) is the Process ID and the second part (1ba0) is the Thread ID.

If you then switch back to the user mode debugger and break into the application (CTRL+BREAK), you can find the corresponding CLR thread by using !threads:

0:013> !threads     // list all CLR threads
ThreadCount: 12
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ   State     GC       Context       Domain   Count APT Exception
   0    1  b70 00180fd0   200a020 Enabled  00000000:00000000 0014c100     0 MTA
   2    2 1b54 00152480      b220 Enabled  00000000:00000000 0014c100     0 MTA (Finalizer)
   3    3 1ba0 0019a1c0   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   4    4 1f9c 0019c138   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   5    5  210 0019cd18   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   6    6 13e0 0019d8d0   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   7    7 17e0 0019e488   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   8    8 1204 0019f040   200b020 Enabled  00000000:00000000 0014c100     0 MTA
   9    9 1ec0 0019fbf8     b020  Disabled 00000000:00000000 0014c100     0 MTA
  10    a 1a48 001a07b0     b020  Disabled 00000000:00000000 0014c100     0 MTA
  11    b 1558 001a1368   200b020 Enabled  00000000:00000000 0014c100     0 MTA
  12    c 1d88 001a1f20   200b020 Enabled  00000000:00000000 0014c100     0 MTA

The third column in the thread list is called OSID and contains the operating system thread id. If you look for the thread ID 1ba0 which we retrieved from the kernel debugger's Cid, you will find that thread #3 is the one who blocks the Mutex. This is the same information which we got from the first approach, but now its a 100% deterministic and a lot simpler as well. I just needed to let go of my fear of kernel debugging before venturing in this direction ...

Am I back? Let's see ...

Ingo — Sat, 05 Aug 2006 09:06:00 GMT

Yes, it's been a long while since my last post in Nov 2005. The short story of what has happend since about middle of last year: Rebecca is now 8 months and a bit and she's doing great, I've spent 43 weeks continously on the road (minus 2 weeks when Rebecca was born and minus 1 week when we moved to another country) and I took a break of about eight weeks afterwards, mainly enjoying time with Becky and Katja, and started to learn gliding as we're living near a small airfield. Oh, yes, and I'm now living in Germany, near Landshut.

During the 43 weeks, I was able to work with a number of fantastic people and great teams. I spent even more time than before with the optimization of large-scale transaction processing systems and for the last few weeks, I've been spending way too much time with WinDbg, CDB and KD. So much time, in fact, that I started to prefer to console versions over WinDbg.

Rebecca Rammer, born November 12, 2005

Ingo — Mon, 14 Nov 2005 02:31:00 GMT

On Saturday, November 12, 2005 at 10:17pm, Rebecca Rammer was born.

The technical data is well within the specs (3040 grams, 48 cm, 10 days early), and baby and wife (and father) are doing great! :-)

Latency vs. Bandwidth – Developers vs. Einstein

Ingo — Tue, 08 Nov 2005 19:38:00 GMT

One piece of The Ultimate Wisdom which is quoted quite often is that "chatty interfaces kill the performance of a distributed application". But actually, it's not the chatty interface which kills it - the really limiting factor is instead one of the handful of unchallenged physical constants of this universe: the speed of light. But let me come back to this later.

Whenever something - and this can be something non-physical like a stream of bytes or a huge chunk of extremely physical rocks - needs to move, you can choose between a set of different alternatives in the way you transport it: You can transfer as much as possible in one go, or alternatively, you could take multiple round trips with smaller amounts of your payload. When you're a teenager moving out of your parent's house, you will quite likely just pack your stuff into your and your friend's cars and just hit the road, going back and forth a few times just to get out as quickly as possible. Years later, after you bought and sold the right stock at the right time, you might instead hire someone to move everything from your 8 bedroom home in one state to your new mansion in a different state using just one big truck and trailer. (Unless of course, you had special help with your choice of stocks, in which case somebody will move you with a rather small car to a rather small room in your final roundtrip for the next 15 years.)

Is Bigger Better?

Despite the fact that reducing the number of roundtrips usually decreases the complete processing time, the usage of smaller units of transportation also has a few advantages: you can for example unpack the first boxes and start using their contents while the rest of your flat is still being sent in smaller packages. That’s what we ended up calling streaming. (My wife would now point out the fact that somebody in our family always managed to be out of the country whenever the two of us moved. That’s what we ended up calling slipping away. Unless you are my wife, in which case you would have use a slightly more explicit term.)

You also get the benefit of being able to use the smaller self-contained packages which might arrive out of sequence. In computer systems, this is sometimes implemented by only returning a small response (let’s say only the header information) as the answer of a synchronous request while returning the detailed information asynchronously using a message queuing system. In real life, I tend to implement this during my regular commuter flights: no matter whether or not my checked bags are delayed or re-routed, I will always have my computer, a power adapter, a toothbrush, and clothes for the next day in my carry on luggage. Especially when traveling via CDG or LHR.

The Speed Of Light – Or: In Doubt, Assume Bandwidth

But in any case: the general recommendation is that chunky interfaces are better than chatty ones. This suggestion is based on the belief that, in doubt, you should assume high bandwidth but not low latency. And this belief in turn is grounded in one ultimate fact: the former can be bought with money – the latter can’t.

I’ve been online since 94. At that time I used a 1200 baud modem to connect to the Internet via terminal dial-in to a Unix box. For me the WWW was Lynx, but that’s a completely different story. At that time, I could send a ping from Europe to the US in about 1200 milliseconds. Today, I can roundtrip the same ping in about 120 milliseconds. But today, I can download the full 3629.6 MB of Visual Studio 2005 Team Suite in approximately 6 hours from a random hotel room. This is coincidentally what I’m doing right now which triggered the writing of this article.

The Long Walk

If I would have done the same thing back in ’94, it would have taken roughly 367 days to transfer the 3,805,911,450 bytes with approximately 120 bytes per second, including start/stop bits and hardware compression. Just to put this into perspective: let’s assume that your hotel room is at the point on this earth which is the farthest away from Redmond. (The fact that penguins will be the only neighbors on this small island might make you think again about the likely roots of the Linux mascot.) If you would have received divine help to walk over water towards the Microsoft HQ, something interesting would have happened: With a swift pace of 5 kilometers (3.1 miles) per hour for 12 hours a day, you would have finished the roughly 20,000 kilometers (12,427 miles) on the earth’s surface in 333 days (23.7 fortnights) which means that you would have had your hands on Visual Studio about a month earlier than your friend who started the download at the same time when you left the island.

Now, of course, this would not have helped you too much as you would have had to wait two more years for a DVD player to become available 1997.

But I think that it’s really interesting to see that the end-to-end bandwidth increased by 1468 times within the last 11 years while the latency (the time a single ping takes) has only been improved tenfold. If this wouldn’t be enough, there is even a natural cap on latency. The minimum round-trip time between two points of this earth is determined by the maximum speed of information transmission: the speed of light. At roughly 300,000 kilometers per second (3.6 * 10E12 teraangstrom per fortnight), it will always take at least 30 milliseconds to send a ping from Europe to the US and back, even if the processing would be done in real time.

That’s why most people recommend chunky interfaces instead of chatty ones to optimize for higher latency instead of smaller bandwidths: The latter will be solved automatically; the former only if you prove Einstein wrong.