一个由Response.Redirect 引起的性能问题的分析

现象：

某系统通过单点登录(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 等成熟日志组件记录日志；