用Windbg调试Silverlight应用死锁

测试一个Silverlight应用时，突然整个IE窗口失去响应（Not Responding）。这时，IE和内嵌的Silverlight应用不响应任何Windows事件，似乎只有杀死IE进程，才能进一步测试。但是，简单地杀死进程，很可能导致问题无法复现（repro）。于是，我将Windbg附加（attach）到IE进程上，做现场调试（live debugging）。

调试.NET程序，需要在Windbg中加载调试扩展项sos.dll。Silverlight的运行时（runtime）是CoreCLR，因此必须加载CoreCLR对应的sos.dll（不能使用.NET Framework自带的sos.dll）。获得正确sos.dll的方法是安装Silverlight Tools for Visual Studio（3.0, 4.0）。如果安装了正确的sos.dll，在Windbg中可用如下命令将其加载。

0:023> .loadby sos coreclr

对于任何一个Windows窗口程序，只有UI线程绘制用户界面。IE窗口失去响应，这暗示UI线程停止工作。于是用!threads命令查看所有线程。

0:023> !threads
ThreadCount:      9
UnstartedThread:  0
BackgroundThread: 7
PendingThread:    0
DeadThread:       2
Hosted Runtime:   yes
                                   PreEmptive   GC Alloc                Lock
       ID  OSID ThreadOBJ    State GC           Context       Domain   Count APT Exception
   4    1   608 0a7098b8   2000220 Enabled  1bf9090c:1bf915dc 109e7fb8     1 STA
  33    2  14e0 0a67fc78      b220 Enabled  00000000:00000000 0a567760     0 MTA (Finalizer)
  34    3   504 0a680b68      1220 Enabled  00000000:00000000 0a567760     0 Ukn
  35    4   46c 0e8b7798   1000220 Enabled  00000000:00000000 0a567760     0 Ukn (Threadpool Worker)
  39    5  2350 0a41bf60   3001220 Enabled  1bf5fe18:1bf615dc 109e7fb8     1 Ukn (Threadpool Worker)
XXXX    a       0a41c970   1011820 Enabled  00000000:00000000 0a567760     0 Ukn (Threadpool Worker)
XXXX    9       0a41a638   1011820 Enabled  00000000:00000000 0a567760     0 Ukn (Threadpool Worker)
  47    6  1618 0a41ce78   3001220 Enabled  1bf91700:1bf935dc 109e7fb8     0 Ukn (Threadpool Worker)
  42    8  2754 0a41c468   3001220 Enabled  1bf93710:1bf955dc 109e7fb8     0 Ukn (Threadpool Worker)

由于UI线程是STA线程，所以可以断定4号线程是UI线程。于是切换到4号线程，用!CLRStack命令检查其托管栈。

0:023> ~4s
eax=0000539e ebx=0244c8b8 ecx=0c4a19f4 edx=00000005 esi=00000001 edi=00000000
eip=776464f4 esp=0244c868 ebp=0244c904 iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00200246
ntdll!KiFastSystemCallRet:
776464f4 c3              ret

0:004> !CLRStack
OS Thread Id: 0x608 (4)
Child SP IP       Call Site
0244cac4 776464f4 [GCFrame: 0244cac4]
0244cbdc 776464f4 [HelperMethodFrame_1OBJ: 0244cbdc] System.Threading.Monitor.Enter(System.Object)
0244cc24 024b117f MyApp.Common.Logger.Log(MyApp.GeneralServiceReference.Level, System.String,
                  MyApp.GeneralServiceReference.ClientLoggingAttributes)
0244cc84 024b0d82 MyApp.Common.UsersUsageTracer.Log(MyApp.Common.UsageCategoryType,
                  MyApp.Common.Event, MyApp.Common.TraceLevel, MyApp.Common.UsageParametes[])
0244cd18 067ddc3b MyApp.BookInfo.BookInfoPresenter.set_Book(MyApp.BookServiceReference.BookInfo)
...

由托管栈可知，UI线程正在调用函数Monitor.Enter，以请求一把排他锁。由于UI线程始终无法获得这把锁，于是UI线程停止工作。申请锁的函数是Logger.Log。这是可以理解的：大多数日志类（Logger）都会在记录日志时，申请排它锁，以确保日志内容的多线程安全。那么这把挂起UI线程的锁是被谁持有呢？

CLR会为每一个被加锁的对象分配一个同步块（sync block），以记录必要的同步信息。用调试器命令!SyncBlk可以查看进程的所有同步块。

0:004> !SyncBlk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock ...
1364 1ae8c1a4            3         1 0a41bf60 2350  39   0c4a19f4 ...

很幸运，进程只有一个同步块，它应该是挂起UI线程的“元凶”。现在，它被线程2350（操作系统线程号）所持有。于是切换到这个工作线程，用!CLRStack命令检查其托管栈。

0:004> ~~[2350]s
eax=00000001 ebx=15c4eb00 ecx=00000001 edx=00000000 esi=00000001 edi=00000000
eip=776464f4 esp=15c4eab0 ebp=15c4eb4c 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:
776464f4 c3              ret

0:039> !CLRStack
Child SP IP       Call Site
15c4ed10 776464f4 [HelperMethodFrame_1OBJ: 15c4ed10] System.Threading.WaitHandle.WaitOneNative
                  (System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean)
15c4ed84 0e279584 System.Threading.WaitHandle.InternalWaitOne
                  (System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean)
15c4eda0 0e279552 System.Threading.WaitHandle.WaitOne(Int64, Boolean)
15c4edb4 0e279440 System.Threading.WaitHandle.WaitOne(Int32, Boolean)
15c4edc8 0e2794d0 System.Threading.WaitHandle.WaitOne()
15c4edd0 5e59223d System.Windows.Threading.Dispatcher.Invoke
                  (System.Windows.Threading.DispatcherPriority, System.Delegate, System.Object[])
15c4edf0 5e5ed437 System.Windows.Threading.DispatcherSynchronizationContext.Send
                  (System.Threading.SendOrPostCallback, System.Object)
15c4ee04 5e638404 System.Net.Browser.AsyncHelper.BeginOnUI(System.Threading.SendOrPostCallback,
                  System.Object)
15c4ee18 5e6395a9 System.Net.Browser.BrowserHttpWebRequestCreator.Create(System.Uri)
15c4ee4c 0406764c System.ServiceModel.Channels.HttpChannelFactory.GetWebRequest
                  (System.ServiceModel.EndpointAddress, System.Uri, System.TimeSpan)
...
15c4f204 067dd666 MyApp.Services.GeneralServiceHandler.CallToServer(ServiceCallDelegate)
15c4f258 067dd50c MyApp.Services.GeneralServiceHandler.RetrieveLoggingProperties
                  (System.EventHandler`1<MyApp.GeneralServiceReference
                  .RetrieveLoggingPropertiesCompletedEventArgs>)
15c4f270 067dd42b MyApp.Common.Logger.LoadLoggingProperties()
...

该工作线程调用函数Logger.LoadLoggingProperties。从函数名推断，该函数是加载日志的属性。从调用栈分析，它使用WCF（调用了名空间System.ServiceModel的类）以获得服务端数据。令人惊讶的是，WCF竟然调用函数Browser.AysncHelper.BeignOnUI，从而将计算任务分配给UI线程。而BeginOnUI调用函数Threading.Dispatcher.Invoke，这是一个对UI线程的同步调用：只有UI线程完成了对System.Delegate对象的调用，函数Invoke才返回。

于是，获知死锁的原因：

1. UI线程请求一把锁，该锁被工作线程锁持有。UI线程等待工作线程释放锁。
2. 工作线程同步调用UI线程，等待UI线程完成任务。
3. UI线程与工作线程相互等待，形成死锁。

到目前为止，我不清楚为什么Silverlight中的WCF会同步调用UI线程。事实上，程序员只能用异步函数调用UI线程，为什么框架本身要同步函数调用UI线程？也许，这是Silverlight团队的一个特殊设计，用于解决更底层的问题。那么，如何解决当前的死锁问题？由于死锁是由函数LoadLoggingProperties引发的，于是检查其实现。

private static void LoadLoggingProperties()
{
    lock (loggingMsgs)
    {
        GeneralServiceHandler.RetrieveLoggingProperties(
            delegate(object sender, RetrieveLoggingPropertiesCompletedEventArgs e)
                {
                    loggingProperties = e.Error == null
                                            ? e.Result
                                            : new LoggingProperties
                                                  {
                                                      LevelThreshold = Level.Warning,
                                                      SendClientLogsToServer = true,
                                                      SendClientUsageLogsToServer = false
                                                  };
                    HandleLogMsgs(null);
                });
    }
}

坦白地说，我不喜欢使用匿名委托（anonymous delegate）的程序。它们虽然看上去很酷，但是往往有一些明显的缺点。

1. 可测试性差。我无法直接测试匿名委托，这导致测试粒度的增大与测试复杂性的提高。
2. 可理解性差。由于是“匿名”的，我无法使用“命名”这一强大的工具来展示程序的意图。
3. 增加耦合性。匿名委托往往导致不同目标、不同抽象级别的代码混杂在一个函数中。

这次死锁的根本原因是不正确的加锁范围，诱因是匿名委托导致的耦合。函数LoadLoggingProperties完成了两件任务：(1) 调用WCF，获得服务端数据；(2) 利用服务端数据，更新客户端数据（loggingProperties）。只有任务(2)是需要加锁保护的。不幸的是，两个任务被匿名委托耦合为一个语句。程序员没有经过深思熟虑，就对整个语句加锁，导致执行任务(1)时引发死锁。

根据以上分析，不难获得解除死锁的方法：缩小加锁范围，将lock语句移入异步WCF调用的回调函数，从而只对任务(2)加锁。

对于这次调试过程，做一个小结：

1. 不使用调试器，很可能会漏掉一些难以复现的缺陷。
2. ！SyncBlk可以查看所有的同步块，是调试死锁的好帮手。
3. 了解应用的线程模型对于调试死锁有帮助。例如，UI线程是STA线程，Threading.Dispatcher.Invoke是同步调用等。
4. 加锁范围要尽可能的小。这是一条基本原则，但是常常被程序员遗忘。
5. 尽量避免对第三方代码加锁，因为你往往不知道它会执行什么操作。