• 用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. 尽量避免对第三方代码加锁,因为你往往不知道它会执行什么操作。
  • 相关阅读:
    git 删除远程分支
    测试模板--接口测试
    测试模板--PC浏览器兼容性测试
    Mock作用
    Docker实践--搭建JIRA平台
    Docker实践--搭建分布式UI测试环境
    Docker实践--搭建HttpRunnerManager测试平台
    Docker实践--搭建Yapi测试平台
    微博爬虫实践---搜索关键词
    接口实践--演练地址集合
  • 原文地址:https://www.cnblogs.com/liangshi/p/1805857.html
Copyright © 2020-2023  润新知