现象：
某系统通过单点登录(SSO) 技术验证用户登录。用户在SSO 系统上通过验证后，跳转到某系统的主页上面。而跳转的时间很长，约1分钟以上。
分析步骤：
在问题复现时抓取Hang dump 进行分析：
1) 找到用户登陆的调用堆栈
|
0:071> kb RetAddr : Args to Child : Call Site 000007fe`f81889e5 : 00000000`0d379e30 00000000`0d379490 00000000`0d378ba0 00000000`00000000 : MSVCR100_CLR0400!memcpy+0x266 000007fe`f818915c : 00000000`0d378b70 000007fe`f8251a30 00000000`0000252c 000007fe`f398d1c8 : clr!StackFrameIterator::ProcessCurrentFrame+0x56a 000007fe`f818936a : 00000000`00000000 00000000`0d378b70 000007fe`f398d19c 00000000`0d378b70 : clr!StackFrameIterator::NextRaw+0x35c 000007fe`f8188d8c : 00000000`0d379420 00000000`00000002 00000000`00000002 00000000`0d378f40 : clr!StackFrameIterator::Next+0x22 000007fe`f826e2a7 : 00000000`0e0936d0 00000000`0e0936d0 00000000`00000000 00000000`00000000 : clr!Thread::StackWalkFramesEx+0x9e 000007fe`f83350f0 : 00006dae`0a62919f 00000000`0e0936d0 00000000`00000000 00000000`00000000 : clr!Thread::ReadyForAsyncException+0x197 000007fe`f833503b : 00000000`0e0936d0 00000000`00000028 00000000`0e0936d0 000007fe`f87cec00 : clr!Thread::HandleThreadAbort+0x6c 000007fe`f83352d7 : 00000000`00000000 00000000`037bc050 00000000`0e0936d0 000007fe`f87cece0 : clr!CommonTripThread+0x18 000007fe`f81b6615 : 000007fe`f81b6470 00000000`00000000 00000000`00001ad6 00000001`00000028 : clr!FC_GCPoll+0x107 000007fe`f398d1c8 : 00000001`5ff74050 00000000`00001296 00000001`5ff76c08 00000000`00000000 : clr!Buffer::BlockCopy+0x1a5 000007fe`f36b932a : 00006dae`d26d74e7 000007fe`f87cdfc0 00000000`0d37dce8 00000000`00000000 : System_Xml_ni!System.Xml.XmlTextReaderImpl.ShiftBuffer(Int32, Int32, Int32)+0x28 000007fe`f36b8c6d : 00000000`0d37b4d0 00000001`5ff76c08 00000014`00054cfe 000007fe`f718f13e : System_Xml_ni!System.Xml.XmlTextReaderImpl.ParseText(Int32 ByRef, Int32 ByRef, Int32 ByRef)+0x19a 000007fe`f36b8a87 : 00000002`3067ffe0 000007fe`f36c0cdb 000007fe`f37578c0 00000002`30680008 : System_Xml_ni!System.Xml.XmlTextReaderImpl.ParseText()+0x6d 000007fe`f36c02f9 : 00000001`5ff740b0 000007fe`f36bfd6d 00000001`5ff74060 00000001`5ff74050 : System_Xml_ni!System.Xml.XmlTextReaderImpl.ParseElementContent()+0x27 000007fe`f3703caa : 00000001`5ff73a30 00000002`6f9e4320 00000001`5ff74038 00000001`5ff74040 : System_Xml_ni!System.Xml.XmlLoader.LoadNode(Boolean)+0xf9 000007fe`f37036e0 : 00000001`5ff74038 00000001`5ff74040 00000001`5ff738e8 00000000`0d37b670 : System_Xml_ni!System.Xml.XmlLoader.LoadDocSequence(System.Xml.XmlDocument)+0x4a 000007fe`f370308d : 00000001`5ff738e8 00000002`7f992078 00000001`5ff738e8 00000000`0d37b6f0 : System_Xml_ni!System.Xml.XmlDocument.Load(System.Xml.XmlReader)+0x90 000007ff`004007f6 : 00000000`23a3db85 000007fe`f71f1590 00000000`00000000 00000000`00000000 : System_Xml_ni!System.Xml.XmlDocument.Load(System.String)+0xcd 000007ff`0040039c : 00000001`5ff732b0 00000002`6f9e4320 00000001`8f98ee20 80000000`00000001 : XXXXXX_Sql_Common!Common.XmlHelper.InsertNode(System.String, System.String, Boolean, System.String, System.Collections.Hashtable, System.Collections.Hashtable)+0xb6 000007ff`00400060 : 00000002`0f980e00 00000001`5ff72c48 00000001`3f98b328 000007fe`f8266279 : XXXXXX_Sql_Common!Common.ErrorLog.Insert(System.String, System.String, System.String)+0x30c 000007ff`004defbc : 00000002`0f980e00 00000001`5ff72ba8 00000001`3f98b328 00000000`0d37c2c0 : XXXXXX_Sql_Common!Common.ErrorLog.Insert(System.String, System.Exception, System.String)+0x60 000007fe`f82665ed : 00000000`0e0936d0 00000000`0e0936d0 000007ff`004def74 00000000`0d37c370 : XXXXXX_Web!EasyMail.Web.login.Page_Load(System.Object, System.EventArgs)+0x19ec 000007fe`f82663f2 : 00000000`0377e3a0 000007ff`004def74 00000000`0d37dea0 000007ff`004cbe98 : clr!ExceptionTracker::CallHandler+0x1c1 000007fe`f8266342 : 00000000`0d37dea0 00000000`0d37bc80 00000000`0377e3a0 00000000`0d37dea0 : clr!ExceptionTracker::CallCatchHandler+0x7e 00000000`76ec9d8d : 000007ff`004de400 00000000`0d37dea0 00000000`0d37c2c0 00000000`0d37bc80 : clr!ProcessCLRException+0x2d6 00000000`76eb8a2c : 00000000`0d380000 00000000`0d37c2c0 00000206`0005af30 000007fe`f81e9b05 : ntdll!RtlpExecuteHandlerForUnwind+0xd 000007fe`f82686a0 : 00000000`0d37dea0 00000000`0000bad0 00000000`0d37d960 00000000`0e0936d0 : ntdll!RtlUnwindEx+0x539 000007fe`f826865c : 00000000`00000000 00000000`0377e3a0 00000000`0d37c940 00000000`0d37dea0 : clr!ClrUnwindEx+0x40 00000000`76ec9d0d : 000007ff`004de481 00000000`0d37dea0 00000000`0d37d330 00000000`0d37c940 : clr!ProcessCLRException+0x2a0 00000000`76eb91af : 00000000`0d380000 000007fe`cd224604 00000000`0005af30 00000000`036ece50 : ntdll!RtlpExecuteHandlerForException+0xd 00000000`76eb97a8 : 00000000`0d37d960 00000000`0d37d330 00000000`00000001 00000000`00000000 : ntdll!RtlDispatchException+0x45a 000007fe`fd0b9e5d : 00000000`0e0936d0 00000000`00000001 00000000`00000001 00000000`0e0936d0 : ntdll!RtlRaiseException+0x22f 000007fe`f8266d1d : 00000000`0e0936d0 00000000`00000001 00000000`0d37dbf1 00000001`5ff72ba8 : KERNELBASE!RaiseException+0x39 000007fe`f826f91e : 00000000`0d37dbd8 00000001`5ff72ba8 00000000`0e0936d0 00000001`5ff72ba8 : clr!RaiseTheExceptionInternalOnly+0x363 000007fe`f826f76b : 00000000`ffb07948 00000000`00000001 00000000`0e0936d0 00000000`0e0936d0 : clr!Thread::UserAbort+0x19a 000007fe`f71b5929 : 00000002`7f992078 00000001`5ff72b90 00000000`00000000 00000000`00000000 : clr!ThreadNative::Abort+0x14b 000007fe`cd19b9a6 : 00000000`ffb45ad0 00000001`dfe872a8 00000001`8f98edc0 00000000`00000000 : mscorlib_ni!System.Threading.Thread.Abort(System.Object)+0x39 000007ff`004de481 : 00000002`0f980da0 00000001`dfe86a90 00000001`3f98b328 80000000`00000000 : System_Web_ni!System.Web.HttpResponse.End()+0x166 000007fe`fad79c09 : 00000001`ef9f1b18 00000001`ef9f1b18 00000001`3f98add0 00000000`0d37e680 : XXXXXX_Web!XXXXXX.Web.login.Page_Load(System.Object, System.EventArgs)+0xeb1 000007fe`cd1b9217 : 00000001`efa2bfb8 000007fe`cd19e96b 00000000`00000000 00000000`00000000 : System_Web_RegularExpressions_ni!System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)+0x19 000007fe`cd1b4d38 : 00000001`efa01d90 00000000`ffb68778 00000000`ffb68501 000007fe`cd19ad55 : System_Web_ni!System.Web.UI.Control.LoadRecursive()+0x47 000007fe`cd1b4011 : 00000001`ef9f1b18 000007fe`cd1b6601 00000000`00000001 000007fe`cd1a4f38 : System_Web_ni!System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)+0xbf8 000007fe`cd1b3ebd : 00000001`ef9f1b18 00000002`7f9980a0 00000000`ffb68501 00000000`00000004 : System_Web_ni!System.Web.UI.Page.ProcessRequest(Boolean, Boolean)+0xc1 000007fe`cd1b2cb7 : 00000001`ef9f1b18 000007fe`cd19fc2a 000007ff`00143cf0 000007fe`cd1bc313 : System_Web_ni!System.Web.UI.Page.ProcessRequest()+0x10d 000007ff`004dc5e3 : 00000000`0d37e850 00000001`efa01d90 00000000`ffb683c0 00000000`0d37e8d0 : System_Web_ni!System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)+0xa7 000007fe`cd1bc7a1 : 00000001`ef9f1b18 00000000`ffb45810 00000001`3fa5bb88 00000000`00000000 : App_Web_0khihdrb!ASP.login_aspx.ProcessRequest(System.Web.HttpContext)+0x33 000007fe`cd1891fe : 00000000`ff9c0001 00000000`ffa11980 00000000`ffb683c0 00000000`00000001 : System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()+0x271 000007fe`cd19d49a : 00000001`3fa59cc8 00000001`3fa5bc50 00000000`0d37eab0 000007fe`cd29fd68 : System_Web_ni!System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)+0x10e 000007fe`cd1886e1 : 00000001`3fa5b9a0 00000000`00000000 00000002`7f9980a0 00000000`0d37ebb0 : System_Web_ni!System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)+0x20a 000007fe`cd18d6ae : 01ce7e07`d83d1609 00000000`ffa6e3b8 00000000`00000000 00000000`00000004 : System_Web_ni!System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)+0xf1 000007fe`cd18c377 : 00000000`ff9bf918 00000000`ffb44b30 00000000`0d37ebf0 00000000`00000000 : System_Web_ni!System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)+0x26e 000007fe`cd90f80d : 00000000`ffa68ed8 00000000`00000000 000007fe`f71ab630 000007fe`f87ce8b0 : System_Web_ni!System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)+0x1c7 000007fe`f8249b9e : 00000000`0124fda0 00000000`01338310 00000000`00000002 00000000`0d37f330 : System_Web_ni!DomainNeutralILStubClass.IL_STUB_COMtoCLR(Int64, Int32, Int32 ByRef)+0x1d 000007fe`f8249782 : 00000000`0383a7d0 000007fe`f81e8244 00000000`0d37f0a8 00000000`00000000 : clr!COMToCLRDispatchHelper+0x4e 000007fe`f8249686 : 00000000`00000000 000007fe`cd11a308 00000000`ffa68ed8 00000000`0d37f2d0 : clr!COMToCLRWorkerBody+0x1ca 000007fe`f82495a2 : 00000000`00000002 00000000`00000000 00000000`0d37f3f0 00000000`00000000 : clr!COMToCLRWorkerBody+0xd6 000007fe`f8249e85 : 00000000`00000000 00000000`037733f0 00000000`00000002 00000000`00000000 : clr!COMToCLRWorkerDebuggerWrapper+0x22 000007fe`f8249b47 : 00000000`0e0936d0 00000000`0d37f2d0 00000000`012d8400 00000000`00000001 : clr!COMToCLRWorker+0x44b 000007fe`e1f122d6 : 00000000`0124fda0 00000000`01338310 00000000`00000002 00000000`0d37f330 : clr!GenericComCallStub+0x57 000007fe`e1f12e06 : 00000000`00000001 00000000`0e91aa10 00000000`00000000 00000000`0d37f950 : webengine4!HttpCompletion::ProcessRequestInManagedCode+0x1e8 000007fe`e1f12dc3 : 00000000`01338310 00000000`00000000 ffffffff`fffffffe 00000000`00000000 : webengine4!HttpCompletion::ProcessCompletion+0x5c 000007fe`f82413d5 : 000007fe`e1f12da0 00000000`0d37f870 00000000`00000000 000007fe`f89cdfa0 : webengine4!CorThreadPoolWorkitemCallback+0x24 000007fe`f8240908 : 00000000`0e0936d0 00000000`00000001 00000000`00000000 00000000`d73646db : clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x181 000007fe`f834b7bf : 00000000`00000001 00000000`0ecd3c01 00000002`00000804 00000003`001a001a : clr!ThreadpoolMgr::NewWorkerThreadStart+0x2e5 000007fe`f8349b56 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : clr!ThreadpoolMgr::WorkerThreadStart+0x3b 00000000`76d9652d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : clr!Thread::intermediateThreadProc+0x7d 00000000`76ecc521 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d |
在堆栈中，以上标红的部分有一个Thread.Abort() 调用，这会引发TheadAbortException 异常的抛出。
2) 提取异常对象进行查看：
|
0:071> !do 00000001`5ff72ba8 Name: System.Threading.ThreadAbortException MethodTable: 000007fef72b6ef0 EEClass: 000007fef6df1860 Size: 160(0xa0) bytes File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll Fields: MT Field Offset Type VT Attr Value Name 000007fef72b6738 400004b 8 System.String 0 instance 0000000000000000 _className 000007fef72b7760 400004c 10 ...ection.MethodBase 0 instance 0000000000000000 _exceptionMethod 000007fef72b6738 400004d 18 System.String 0 instance 0000000000000000 _exceptionMethodString 000007fef72b6738 400004e 20 System.String 0 instance 000000015ff72c48 _message 000007fef72d9bc8 400004f 28 ...tions.IDictionary 0 instance 0000000000000000 _data 000007fef72b6b00 4000050 30 System.Exception 0 instance 0000000000000000 _innerException 000007fef72b6738 4000051 38 System.String 0 instance 0000000000000000 _helpURL 000007fef72b5890 4000052 40 System.Object 0 instance 000000015ff72d50 _stackTrace 000007fef72b5890 4000053 48 System.Object 0 instance 0000000000000000 _watsonBuckets 000007fef72b6738 4000054 50 System.String 0 instance 0000000000000000 _stackTraceString 000007fef72b6738 4000055 58 System.String 0 instance 0000000000000000 _remoteStackTraceString 000007fef72bc620 4000056 88 System.Int32 1 instance 0 _remoteStackIndex 000007fef72b5890 4000057 60 System.Object 0 instance 0000000000000000 _dynamicMethods 000007fef72bc620 4000058 8c System.Int32 1 instance -2146233040 _HResult 000007fef72b6738 4000059 68 System.String 0 instance 0000000000000000 _source 000007fef72c3318 400005a 78 System.IntPtr 1 instance 0 _xptrs 000007fef72bc620 400005b 90 System.Int32 1 instance -532462766 _xcode 000007fef72b6248 400005c 80 System.UIntPtr 1 instance 7fef71b5929 _ipForWatsonBuckets 000007fef72eb600 400005d 70 ...ializationManager 0 instance 000000015ff72c70 _safeSerializationManager 0:071> !do 000000015ff72c48 Name: System.String MethodTable: 000007fef72b6738 EEClass: 000007fef6e3ed68 Size: 40(0x28) bytes File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll String: 正在中止线程。 Fields: MT Field Offset Type VT Attr Value Name 000007fef72bc620 4000103 8 System.Int32 1 instance 7 m_stringLength 000007fef72bb160 4000104 c System.Char 1 instance 6b63 m_firstChar 000007fef72b6738 4000105 10 System.String 0 shared static Empty >> Domain:Value 00000000037733f0:000000015f980488 000000000383a7d0:000000015f980488 << |
3) 根据堆栈显示，异常对象抛出之后，被程序代码捕获并通过XXXXXX_Sql_Common!Common.ErrorLog.Insert() 记录下来：
|
000007fe`f398d1c8 : 00000001`5ff74050 00000000`00001296 00000001`5ff76c08 00000000`00000000 : clr!Buffer::BlockCopy+0x1a5 000007fe`f36b932a : 00006dae`d26d74e7 000007fe`f87cdfc0 00000000`0d37dce8 00000000`00000000 : System_Xml_ni!System.Xml.XmlTextReaderImpl.ShiftBuffer(Int32, Int32, Int32)+0x28 000007fe`f36b8c6d : 00000000`0d37b4d0 00000001`5ff76c08 00000014`00054cfe 000007fe`f718f13e : System_Xml_ni!System.Xml.XmlTextReaderImpl.ParseText(Int32 ByRef, Int32 ByRef, Int32 ByRef)+0x19a 000007fe`f36b8a87 : 00000002`3067ffe0 000007fe`f36c0cdb 000007fe`f37578c0 00000002`30680008 : System_Xml_ni!System.Xml.XmlTextReaderImpl.ParseText()+0x6d 000007fe`f36c02f9 : 00000001`5ff740b0 000007fe`f36bfd6d 00000001`5ff74060 00000001`5ff74050 : System_Xml_ni!System.Xml.XmlTextReaderImpl.ParseElementContent()+0x27 000007fe`f3703caa : 00000001`5ff73a30 00000002`6f9e4320 00000001`5ff74038 00000001`5ff74040 : System_Xml_ni!System.Xml.XmlLoader.LoadNode(Boolean)+0xf9 000007fe`f37036e0 : 00000001`5ff74038 00000001`5ff74040 00000001`5ff738e8 00000000`0d37b670 : System_Xml_ni!System.Xml.XmlLoader.LoadDocSequence(System.Xml.XmlDocument)+0x4a 000007fe`f370308d : 00000001`5ff738e8 00000002`7f992078 00000001`5ff738e8 00000000`0d37b6f0 : System_Xml_ni!System.Xml.XmlDocument.Load(System.Xml.XmlReader)+0x90 000007ff`004007f6 : 00000000`23a3db85 000007fe`f71f1590 00000000`00000000 00000000`00000000 : System_Xml_ni!System.Xml.XmlDocument.Load(System.String)+0xcd 000007ff`0040039c : 00000001`5ff732b0 00000002`6f9e4320 00000001`8f98ee20 80000000`00000001 : EasyMail_Sql_Common!Common.XmlHelper.InsertNode(System.String, System.String, Boolean, System.String, System.Collections.Hashtable, System.Collections.Hashtable)+0xb6 000007ff`00400060 : 00000002`0f980e00 00000001`5ff72c48 00000001`3f98b328 000007fe`f8266279 : EasyMail_Sql_Common!Common.ErrorLog.Insert(System.String, System.String, System.String)+0x30c 000007ff`004defbc : 00000002`0f980e00 00000001`5ff72ba8 00000001`3f98b328 00000000`0d37c2c0 : EasyMail_Sql_Common!Common.ErrorLog.Insert(System.String, System.Exception, System.String)+0x60 000007fe`f82665ed : 00000000`0e0936d0 00000000`0e0936d0 000007ff`004def74 00000000`0d37c370 : EasyMail_Web!EasyMail.Web.login.Page_Load(System.Object, System.EventArgs)+0x19ec 000007fe`f82663f2 : 00000000`0377e3a0 000007ff`004def74 00000000`0d37dea0 000007ff`004cbe98 : clr!ExceptionTracker::CallHandler+0x1c1 |
4) 通过进一步检查，发现记录日志的文件在D:\XXXX\SysLog\ErrorLog.XML
|
0:071> !do 00000002`6f9e4320 Name: System.String MethodTable: 000007fef72b6738 EEClass: 000007fef6e3ed68 Size: 86(0x56) bytes File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll String: D:\XXXX\SysLog\ErrorLog.XML Fields: MT Field Offset Type VT Attr Value Name 000007fef72bc620 4000103 8 System.Int32 1 instance 30 m_stringLength 000007fef72bb160 4000104 c System.Char 1 instance 44 m_firstChar 000007fef72b6738 4000105 10 System.String 0 shared static Empty >> Domain:Value 00000000037733f0:000000015f980488 000000000383a7d0:000000015f980488 << |
原因分析：
通过以上分析步骤，可以了解到代码的执行流程大致如下：
a) XXXXXX_Web!XXXXXX.Web.login.Page_Load() 在执行HttpWebResponse.End() 时抛出了ThreadAbortException 异常；
b) 该异常抛出后被程序代码捕获；
c) 捕获的异常信息通过XXXXXX_Sql_Common!Common.ErrorLog.Insert() 方法写入到位于D:\XXXX\SysLog\ErrorLog.XML 的文件中；
首先，页面在执行代码时抛出异常就是不正确的。通过查询KB 了解到，这是一个已知问题:
http://support.microsoft.com/kb/312629
KB 中已经给出了不抛出异常的方法，即使用Response.Redirect() 方法的一个重载:
Response.Redirect(url, false);
其次，通过提取服务器上的日志文件，我们发现这个文件较大，约15MB。通过实际编写程序测试，在这个文件中插入一个异常信息，耗时较多：
这个15MB 的XML 文件在打开，保存是耗时较长。
结论：
由于登录页面在SSO 登录时采用了不恰当的页面跳转方法，导致页面抛出ThreadAbortException 异常，并引发页面打开一个体积较大的XML 文件进行读写。最终导致了页面跳转非常缓慢的现象。尤其是在多人同时访问时，导致了对XML 日志文件的争用。导致用户并发访问量越大，跳转速度越慢。
修复建议：
1) 使用Respons.Redirect(uri, false); 实现页面跳转；
2) 使用普通文本格式记录日志替代XML 格式，以便提高速度；
3) 使用Log4Net 等成熟日志组件记录日志；