背景/介绍:
非常奇怪的问题,在引发特定异常时,似乎所有其他线程都停止执行,直到异常被处理。该应用程序是一个代理服务器,通过一个 tcp 套接字池传输多个请求(在任何一个时间范围内有数百个请求),这些请求通过一个 socks 连接连接到 N 个其他代理客户端。这也通过传递委托进行了尝试,而不是使用异常,但性能同样很差。
正常操作下的日志片段:
14:40:17.700 [PrxSvc:9058] --> [200] 1217ms http://redact.example.com
14:40:17.700 [PrxSvc:9058] C-DEBUG:C
14:40:17.716 [PrxSvc:9058] --> [200] 1098ms http://redact.example.com
14:40:17.716 [PrxSvc:9058] C-DEBUG:C
14:40:17.727 [PrxSvc:9054] --> [200] 905ms http://redact.example.com
14:40:17.727 [PrxSvc:9054] C-DEBUG:C
14:40:17.778 [PrxSvc:9050] --> [200] 453ms http://redact.example.com
14:40:17.778 [PrxSvc:9050] C-DEBUG:C
14:40:17.781 [Unnamed Thread] C-DEBUG:A
14:40:17.781 [Unnamed Thread] C-DEBUG:B
14:40:17.796 [PrxSvc:9058] --> [200] 652ms http://redact.example.com
14:40:17.796 [PrxSvc:9058] C-DEBUG:C
14:40:17.807 [PrxSvc:9056] --> [200] 1555ms http://redact.example.com
14:40:17.807 [PrxSvc:9056] C-DEBUG:C
14:40:17.816 [PrxSvc:9064] --> [200] 396ms http://redact.example.com
套接字池重新使用到域的连接,但是当连接被外部服务器关闭时,我们显然不会收到任何通知。当我们尝试通过 TcpSocksHandler.TaskHandler 方法重用这个连接时:
socks.Send(buffer, 0, rcv, SocketFlags.None);
socks.Receive(new byte[1], 0, 1, SocketFlags.Peek);
此异常被以下内容捕获:
catch
{
//The socket is bad, we should get a new socket.
Log("This socket has expired! - Server has closed the connection.");
Log(String.Format("This socket was {0} seconds old: {1}", seconds, socks.Guid));
socks.Dispose();
Log("C-DEBUG:1");
throw new SocksSocketFailureException(); //throw exception. to bubble back up.
}
然后被它的调用代码捕获,多次向上堆栈,如下所示:
DoHandleRequest{...
try
{
_actualEndPoint = TcpSocksHandler.TaskHandler(socket, context.SocksSocket, 30000000, method);
}
catch (SocksSocketFailureException ssfe)
{
context.SocksSocket = null;
Logger.Log("C-DEBUG:2");
throw;
}
}
ProxyBase.HandleRequest{...
try
{
...
success = DoHandleRequest(context, out bytes);
}
catch (SocksSocketFailureException ssfex)
{
Logger.Log("C-DEBUG:3");
throw;
}
}
ProxyManager.HandleRequest{
while (true)
{
// Pick the best available proxy to handle the request
Logger.Log("C-DEBUG:A");
IProxy proxy = GetNextProxy(context) ?? NullProxy.Instance;
Logger.Log("C-DEBUG:B");
try
{
// Process the request
proxy.HandleRequest(context);
Logger.Log("C-DEBUG:C");
break;
}
catch(SocksSocketFailureException ssfex)
{
Logger.Log("C-DEBUG:4");
}
catch (Exception)
{
break;
}
}
}
从下面的日志片段中,您可以看到这个(或缺乏)的性能
14:40:34.090 [PrxSvc:9068] C-DEBUG:A
14:40:34.090 [PrxSvc:9068] C-DEBUG:B
14:40:34.231 [PrxSvc:9068] This socket has expired! - Server has closed the connection.
14:40:34.231 [PrxSvc:9068] This socket was 6.281049 seconds old: 61cc51b9-f121-4529-9649-7defcc1f5586
14:40:34.231 [PrxSvc:9068] C-DEBUG:1
14:40:34.528 [PrxSvc:9068] C-DEBUG:2
14:40:34.715 [PrxSvc:9068] C-DEBUG:3
14:40:34.918 [PrxSvc:9068] C-DEBUG:4
14:40:34.918 [PrxSvc:9068] C-DEBUG:A
上面没有编辑任何日志行 - 几乎整个第二秒都没有处理任何其他内容!(我们通常可以处理一百个请求)。此外,仅仅将异常冒泡到堆栈中的行为似乎需要一秒钟(有时更多!)。- 请注意上述日志行的时间安排。例如 DEBUG:3 和 DEBUG:4 之间有 0.2 秒的间隔!!
我不知道是什么原因造成的。任何建议/想法将不胜感激!
更新:
基于 Eamon 的问题,我将相同的 x64 构建推送到运行 Windows8 64 位的非生产本地机器。安装为服务,发布构建,就像前面的例子一样。唯一的另一个区别是它现在针对 4 个代理节点(PrxSvc 9050、9052、9054、9056),而不是之前的 80 个。我不能再说这些异常步骤现在是否阻塞了线程执行,因为它们是在一个及时时尚:
16:53:59.787 [PrxSvc:9056] This socket has expired! - Server has closed the connection.
16:53:59.787 [PrxSvc:9056] This socket was 0.1280009 seconds old: 69d12cc9-9456-47db-86b2-a2ebf87b41bf
16:53:59.787 [PrxSvc:9056] C-DEBUG:1
16:53:59.787 [PrxSvc:9056] C-DEBUG:2
16:53:59.787 [PrxSvc:9056] C-DEBUG:3
16:53:59.787 [PrxSvc:9056] C-DEBUG:4
16:53:59.787 [PrxSvc:9056] C-DEBUG:A
在这台机器上,代码目前正在以大约每秒 80 个请求的速度愉快地处理 800 个并发请求,并且可以轻松处理更多......到底是什么导致了这种差异?!
为了完整起见,我用 4 个节点而不是 80 个节点重新运行了第一个测试(在 win2008 服务器上),并得到了相同的垃圾结果:
17:22:44.891 [PrxSvc:9054] C-DEBUG:B
17:22:45.063 [PrxSvc:9054] This socket has expired! - Server has closed the connection.
17:22:45.063 [PrxSvc:9054] This socket was 25.84375 seconds old: cfdee74d-9941-4c8c-80cd-f32aa14b7877
17:22:45.063 [PrxSvc:9054] C-DEBUG:1
17:22:45.485 [PrxSvc:9054] C-DEBUG:2
17:22:45.751 [PrxSvc:9054] C-DEBUG:3
17:22:46.016 [PrxSvc:9054] C-DEBUG:4