抛出的异常似乎阻止了其他线程

Question

背景/简介:

非常奇怪的问题,在抛出特定异常时,似乎所有其他线程都停止执行,直到处理异常为止.该应用程序是一个代理服务器,通过一个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之间的差距为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个并发请求,并且可以轻松处理更多......究竟是什么导致了这种差异？!

为了完整性,我重新进行了第一次测试(在win2008服务器上),有4个节点,而不是80个,并得到了相同的垃圾结果:

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

Answer 1

抛出异常的成本很低，捕获异常的成本也很高。除非代码知道如何处理异常，否则不要捕获异常。C-Debug:2 和 C-Debug:3 似乎就是这种情况。此外，您还有一个已知条件，即另一方已关闭其连接。您不应该使用异常来处理此问题。您需要公开一个类似于IsConnected并在循环中检查的方法或属性，而不是依赖于抛出的异常：

while(true) {
   IProxy proxy = GetNextProxy(context) ?? NullProxy.Instance;
   if (!proxy.IsConnected)
       continue;
   try {
     proxy.HandleRequest(context);
     break;
   } catch {
     // handle actual exceptional cases here
   } 
}

如果需要，您可以在上面的代码中添加一个计数器或计时器，并在 x 次重试或特定时间段已过期的情况下抛出异常，但无论如何 IsConnected 属性检查将大大提高代码的性能。