问题现象:
Fiddler跟踪web请求响应时间11秒之多,但从该功能的程序日志记录查看,执行时间只有不到1秒,调阅对应的iis请求响应日志,iis处理时间确实是11秒,抓取dump分析,竟然没有该功能的线程堆栈,很奇怪。。。
问题分析:
多次重现问题并抓取dump分析发现,每次都有一个发生邮件的异步线程在等待,结合PerfView的统计分析,在对应功能操作执行过程中,确实调用了发送异步邮件,为什么会影响当前web请求的线程返回呢?
问题结论:
根据线索找到发送异步邮件的调用代码,发现异步实现使用的是backgroundWorker。经验证,backgroundWorker本身的方法调用是异步执行,但web请求的主线程最终仍然会等待backgroundWorker异步线程执行完才会返回客户端。另外,backgroundWorker设计上是给winform界面做后台处理的,并不适合服务端异步,建议改为ThreadPool或Task异步,注意在异步处理中做异常捕获。
诊断过程:
procdump -ma -s 4 -n 2 9584
OS Thread Id: 0x3584 (166)
Child SP IP Call Site
000000002d09c688 00000000773b98ca [InlinedCallFrame: 000000002d09c688] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000002d09c688 000007fef7136091 [InlinedCallFrame: 000000002d09c688] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000002d09c660 000007fef7136091 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
000000002d09c710 000007fef70b636c System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
000000002d09c790 000007fef70b5f94 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32)
000000002d09c800 000007fef76867d0 System.Net.DelegatedStream.Read(Byte[], Int32, Int32)
000000002d09c850 000007fef7687479 System.Net.BufferedReadStream.Read(Byte[], Int32, Int32)
000000002d09c8b0 000007fef76ae6cd System.Net.Mail.SmtpReplyReaderFactory.ReadLines(System.Net.Mail.SmtpReplyReader, Boolean)
000000002d09c940 000007fef76af37f System.Net.Mail.ReadLinesCommand.Send(System.Net.Mail.SmtpConnection)
000000002d09c970 000007fef76a7175 System.Net.Mail.SmtpConnection.GetConnection(System.Net.ServicePoint)
000000002d09ca20 000007fef76a3306 System.Net.Mail.SmtpClient.GetConnection()
000000002d09ca50 000007fef76a15d0 System.Net.Mail.SmtpClient.Send(System.Net.Mail.MailMessage)
000000002d09caf0 000007fea710ff61 Genersoft.Platform.Message.Engine.Adapters.MailSender.MailSend()
000000002d09d190 000007fea710dca8 Genersoft.Platform.Message.Engine.Adapters.SmtpAdapter.Send(Genersoft.Platform.Message.Entity.GSPMessage)
000000002d09d280 000007fea6fa260e Genersoft.Platform.Message.Engine.MessageEngine.SendMessage(Genersoft.Platform.Message.Entity.GSPMessage)
000000002d09d8e0 000007fea710a836 Genersoft.Platform.Message.Engine.MessageEngine.OnAsyncSendMessageDowork(System.Object, System.ComponentModel.DoWorkEventArgs)
000000002d09d9a0 000007fef70a9028 System.ComponentModel.BackgroundWorker.OnDoWork(System.ComponentModel.DoWorkEventArgs)
000000002d09d9e0 000007fef70a91bb System.ComponentModel.BackgroundWorker.WorkerThreadStart(System.Object)
000000002d09ddd8 000007fef9116d93 [HelperMethodFrame_PROTECTOBJ: 000000002d09ddd8] System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr, System.Object[], System.Object, System.Object[] ByRef)
000000002d09e1b0 000007fef8a9eb94 System.Runtime.Remoting.Messaging.StackBuilderSink.AsyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage, System.Runtime.Remoting.Messaging.IMessageSink)
000000002d09e250 000007fef8083a63 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000002d09e320 000007fef80838f4 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000002d09e350 000007fef80c3993 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
000000002d09e390 000007fef80c2c72 System.Threading.ThreadPoolWorkQueue.Dispatch()
000000002d09e828 000007fef9116d93 [DebuggerU2MCatchHandlerFrame: 000000002d09e828]
000000002d09e9b8 000007fef9116d93 [ContextTransitionFrame: 000000002d09e9b8]
000000002d09ebe8 000007fef9116d93 [DebuggerU2MCatchHandlerFrame: 000000002d09ebe8]