上周四产品上线一切运行正常,做了一点小改动后周四晚上发布,周五大量用户反馈在访问页面时出现长时间等待响应。将4台Web前端的服务器重启,缓存服务器2台重启,问题依旧。由于是生产环境,只能上去查看IIS、Windows日志,没有记录任何异常。于是将版本更新回周四凌晨发布版本,运行正常。据版本跟踪只修改过一个特定模块,但是这个模块不会影响页面的正常访问。于是猜测可能是短时间的网络问题,IIS在这个时间段没有请求访问的日志,不会是程序的性能问题。于是晚上在集成环境恢复周四晚上发布的版本,问题重现,但是周四早上的版本没有问题。
任务管理器显示w3p进程的内存、cpu使用率、线程数都没有变化,应该是一个deadlock。但是周四晚上发布的版本并没有添加或修改过线程同步的代码。对发布的dll进行跟踪排查,发现Memcached.ClientLibrary.dll的大小和早上发布的版本不同。晚上发布的是Debug版本,将Memcached.ClientLibrary.dll更新为Release版本问题解决。于是问题就产生了,为什么Debug和Release版本在同一个环境下,Debug版本会造成deadlock。
用WinDbg附加到w3p进程,进行压力测试,30 – 50用户下出现deadlock。用!runaway查看线程使用cpu时间,大量线程使用cpu时间为0。用~* kb查看所有call stack,大量线程都在等待ntdll!NtWaitForMultipleObjects。用!cs查看临界区,内容太多。修改HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\CriticalSection-Timeout的值为60,便于WinDbg获得更多的超时信息。加载sos.dll,!threads查看所有托管线程,发现一个线程抛出了System.Threading.SynchronizationLockException。用!SyncBlk查看托管代码的lock情况,发现存在两个实例lock和一个RuntimeType lock。继续用~* e !clrstack查看所有的托管线程callstack,发现大部分代码停留在SockIOPool的CheckIn函数,小部分停留在SockIOPool的GetInstance函数和RemoveSocketFromPool函数。根据!SyncBlk显示的三个线程ID,用~线程ID s命令切换到对应线程查看callstack。使用实例lock的线程停留在RemoveSocketFromPool函数,使用RuntimeType的线程停留在CheckIn函数,抛出SynchronizationLockException的线程则停留在GetInstance函数。
于是分析Memcached.ClientLibrary.dll的源代码,发现它在几个函数上使用了MethodImplAttribute,并将函数的属性标示为Synchronized。对于MethodImplOptions.Synchronized,如果函数为static那么它使用RuntimeTypeHandle作为lock,实例函数则使用this指针作为lock。CheckIn为实例函数,而GetInstance、RemoveSocketFromPool为static函数。由于内部代码创建了两个SockIOPool实例,所以在callstack中可以看到它们分别停留在RemoveSocketFromPool函数(CheckIn函数内部会调用RemoveSocketFromPool函数),证明有两个线程独占了this指针。而另一个线程停留在了CheckIn函数,在CheckIn函数前会先调用GetInstance函数,所以它lock了RuntimeType,但正常情况下在调用完GetInstance函数后不应再独占资源。这就是一个典型的deadlock,有两个线程锁住了this指针同时在等待获取RuntimeTypeHandle,而一个线程锁住了RuntimeTypeHandle,同时在等待获取this指针。
知道了现象后情况就很容易模拟,编写一个Console程序部署到x64的机器上运行,问题重现。但是这个问题在x86的机器上没有问题、在x64机器上以x86的兼容性运行也不会存在deadlock。于是大致情况可以确定在x86的机器上编译的Debug版本在x64机器上运行会出现deadlock。通过ildasm查看Debug和Release在IL层级的区别,发现MethodImplOptions.Synchronized会被修饰为cil sync managed,看来这层操作只有在JIT后才会看出代码的区别。
这个时候在Microsoft的Connect上发现有人曾经在09年4月份反馈这么一个现象,当时给出的workround就是使用显示的lock代替MethodImplOptions.Synchronized,同时会在下一个版本的CLR修复。为了验证是否在下一个版本的CLR修复,将同样的测试代码运行在.NET Framework 4.0下没有问题。