抛出的异常似乎正在阻塞其他线程
本文关键字：其他 线程 异常 | 更新日期: 2023-09-27 17:50:45
背景/简介：
这是一个非常奇怪的问题，在抛出特定异常时，所有其他线程似乎都会停止执行，直到异常得到处理。该应用程序是一个代理服务器，通过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
上面没有编辑任何日志行-几乎整秒钟都没有处理任何其他内容！(我们通常可以处理大约一百个请求(。此外，仅仅在堆栈中冒泡一个异常似乎需要一秒钟的时间(有时甚至更长！(。-请注意上述日志行的时间安排。例如，调试：3和调试：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个并发请求，并且可以轻松地处理更多。。。究竟是什么导致了这种差异？！
为了完整性，我用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
这不是你的问题的答案，你的程序中的错误是什么，但如果不看到大局或亲自测试你的代码，我很难判断。通常我会为此写一篇评论，但我的文字太长了。
你的第一个示例日志("正常操作"(让我有点困惑。只有一个C-DEBUG:A和C-DEBUG:B，而至少每个C-DEBUG:C都必须有一个，不是吗？
其他例子看起来不错，一切都如我所料(A=>B=>异常=>1=>2=>3=>4=>A(。嗯，似乎只有一条线索，但这些例子并没有表明这是错误的；我没有看到来自另一个线程的第二个CCD_ 4。你期待什么？
关于您的更新：我想知道更多关于测试机性能的信息，因为每次抛出异常都需要一些执行时间。这就是为什么在循环中抛出异常会对性能造成巨大影响的原因。你的服务器的时间似乎有点慢，但从我的角度来看还可以。
虽然我无法为您的问题提供提示，但至少我可以告诉您，异常抛出本身并不是其他线程的阻塞因素为了证明我写了一个小程序(如果你想知道我是如何做到的，请参阅下面的源代码(。该程序的输出是
19:31:09.2788 [Thread-0] 0
19:31:09.2788 [Thread-1] 1
19:31:09.3908 [Thread-0] 0
19:31:09.3908 [Thread-1] 1
19:31:09.4908 [Thread-1] 1
19:31:09.4908 [Thread-0] 0
19:31:09.5908 [Thread-0] 0
19:31:09.5998 [Thread-1] Caught exception callstack frame 29
19:31:09.6078 [Thread-1] Caught exception callstack frame 28
19:31:09.6148 [Thread-1] Caught exception callstack frame 27
19:31:09.6218 [Thread-1] Caught exception callstack frame 26
19:31:09.6288 [Thread-1] Caught exception callstack frame 25
19:31:09.6358 [Thread-1] Caught exception callstack frame 24
19:31:09.6418 [Thread-1] Caught exception callstack frame 23
19:31:09.6488 [Thread-1] Caught exception callstack frame 22
19:31:09.6548 [Thread-1] Caught exception callstack frame 21
19:31:09.6608 [Thread-1] Caught exception callstack frame 20
19:31:09.6668 [Thread-1] Caught exception callstack frame 19
19:31:09.6728 [Thread-1] Caught exception callstack frame 18
19:31:09.6778 [Thread-1] Caught exception callstack frame 17
19:31:09.6828 [Thread-1] Caught exception callstack frame 16
19:31:09.6888 [Thread-1] Caught exception callstack frame 15
19:31:09.6908 [Thread-0] 0
19:31:09.6938 [Thread-1] Caught exception callstack frame 14
19:31:09.6978 [Thread-1] Caught exception callstack frame 13
19:31:09.7028 [Thread-1] Caught exception callstack frame 12
19:31:09.7078 [Thread-1] Caught exception callstack frame 11
19:31:09.7128 [Thread-1] Caught exception callstack frame 10
19:31:09.7168 [Thread-1] Caught exception callstack frame 9
19:31:09.7218 [Thread-1] Caught exception callstack frame 8
19:31:09.7258 [Thread-1] Caught exception callstack frame 7
19:31:09.7299 [Thread-1] Caught exception callstack frame 6
19:31:09.7339 [Thread-1] Caught exception callstack frame 5
19:31:09.7369 [Thread-1] Caught exception callstack frame 4
19:31:09.7409 [Thread-1] Caught exception callstack frame 3
19:31:09.7439 [Thread-1] Caught exception callstack frame 2
19:31:09.7469 [Thread-1] Caught exception callstack frame 1
19:31:09.7499 [Thread-1] Caught exception callstack frame 0
19:31:09.7509 [Thread-1] 1
19:31:09.7919 [Thread-0] 0
19:31:09.8509 [Thread-1] 1
19:31:09.8919 [Thread-0] 0
19:31:09.9509 [Thread-1] 1
19:31:10.0509 [Thread-1] 1
19:31:10.1509 [Thread-1] 1
19:31:10.2509 [Thread-1] 1
19:31:10.3509 [Thread-1] 1
正如您所看到的，线程thread-0打印0，而thread-1的异常则在调用堆栈中向上运行。这里没有阻塞！
在这里参考我的程序：
class Program {
class MyException : Exception {}
// A class for give the starting thread operation some parameters
class ThreadStartParameter {
// For identifying each thread
public int Id { get; set; }
// For building up a deeper callstack frame
public int CallStackDepth { get; set; }
// Indicates that this thread should throw an exception
public bool ThrowException { get; set; }
}
static void Main(string[] args) {
// Create two threads and let them run concurrently
Thread t0 = new Thread(BuildUpCallStack) { Name = "Thread-0" };
Thread t1 = new Thread(BuildUpCallStack) { Name = "Thread-1" };
t0.Start(new ThreadStartParameter {
Id = 0,
CallStackDepth = 0,
ThrowException = false
});
t1.Start(new ThreadStartParameter {
Id = 1,
CallStackDepth = 0,
ThrowException = true
});
Console.Read();
}
// Recursive helper method to build a callstack of 30 frames, which
// is used to rethrow an exception at each level
static void BuildUpCallStack(object data) {
ThreadStartParameter parameter = (ThreadStartParameter)data;
if (parameter.CallStackDepth < 30) {
try {
BuildUpCallStack(new ThreadStartParameter {
Id = parameter.Id,
CallStackDepth = parameter.CallStackDepth + 1,
ThrowException = parameter.ThrowException
});
} catch (MyException e) {
Log(string.Format("Caught exception callstack frame {0}",
parameter.CallStackDepth));
// If an exception occured, rethrow it unless this
// callstack frame was the first
if (parameter.CallStackDepth != 0) throw;
// If this frame was the first in callstack, restart the
// thread but this time without throwing an exception (for
// demonstrate such a restart character like your Proxies do)
BuildUpCallStack(new ThreadStartParameter {
Id = parameter.Id,
CallStackDepth = 0,
ThrowException = false
});
}
return;
}
DoSomething(parameter);
}
static void DoSomething(object data) {
ThreadStartParameter parameter = (ThreadStartParameter)data;
for (int counter = 0; counter < 7; counter++) {
if (counter == 3 && parameter.ThrowException)
throw new MyException();
Log(parameter.Id);
Thread.Sleep(100);
}
}
static void Log(object message) {
Console.WriteLine(
" {0:HH:mm:ss.ffff} [{1}] {2}",
DateTime.Now,
Thread.CurrentThread.Name,
message.ToString());
}
}
如果你在测试机上尝试这个程序，我想你应该启动更多的"好"线程(不会抛出异常(和/或增加所需的调用堆栈深度，以便像我一样看到效果。
异常抛出成本低，捕获成本高。除非代码知道如何处理异常，否则不要捕获异常。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属性检查都将大大提高代码的性能。