测试一个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 ret0: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 ret0: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才返回。
于是,获知死锁的原因:
- UI线程请求一把锁,该锁被工作线程锁持有。UI线程等待工作线程释放锁。
- 工作线程同步调用UI线程,等待UI线程完成任务。
- 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)的程序。它们虽然看上去很酷,但是往往有一些明显的缺点。
- 可测试性差。我无法直接测试匿名委托,这导致测试粒度的增大与测试复杂性的提高。
- 可理解性差。由于是“匿名”的,我无法使用“命名”这一强大的工具来展示程序的意图。
- 增加耦合性。匿名委托往往导致不同目标、不同抽象级别的代码混杂在一个函数中。
这次死锁的根本原因是不正确的加锁范围,诱因是匿名委托导致的耦合。函数LoadLoggingProperties完成了两件任务:(1) 调用WCF,获得服务端数据;(2) 利用服务端数据,更新客户端数据(loggingProperties)。只有任务(2)是需要加锁保护的。不幸的是,两个任务被匿名委托耦合为一个语句。程序员没有经过深思熟虑,就对整个语句加锁,导致执行任务(1)时引发死锁。
根据以上分析,不难获得解除死锁的方法:缩小加锁范围,将lock语句移入异步WCF调用的回调函数,从而只对任务(2)加锁。
对于这次调试过程,做一个小结:
- 不使用调试器,很可能会漏掉一些难以复现的缺陷。
- !SyncBlk可以查看所有的同步块,是调试死锁的好帮手。
- 了解应用的线程模型对于调试死锁有帮助。例如,UI线程是STA线程,Threading.Dispatcher.Invoke是同步调用等。
- 加锁范围要尽可能的小。这是一条基本原则,但是常常被程序员遗忘。
- 尽量避免对第三方代码加锁,因为你往往不知道它会执行什么操作。