抛出exception似乎阻塞其他线程

背景/简介:

非常奇怪的问题是,在抛出一个特定的exception时,看起来所有其他的线程都会停止执行,直到处理exception。 该应用程序是一个代理服务器,通过一个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 

套接字池阻止连接到域,但是当一个连接被外部服务器closures时,我们显然没有收到这个通知。 当我们尝试通过我们的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秒的间隔!

我不知道是什么原因造成的。 任何build议/想法将不胜感激!

更新:

基于Eamon的问题,我将相同的x64版本推送到运行Windows8 64位的非生产本地机器。 作为服务安装,发布版本,如前面的例子。 唯一的区别就是它现在的目标是4个代理节点(PrxSvc 9050,9052,9054,9056),而不是前面的80.我不能再说这些exception步骤现在是否阻塞线程执行,因为它们在及时时尚:

 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个并发请求,并且可以轻松地处理更多…究竟是什么造成了这种差异?

为了完整性,我重新进行了第一次testing(在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 

这不是你的问题的答案,你的程序中的错误是什么,但是如果没有看到大的图片或者自己测试你的代码,我都难以分辨。 通常我会为此写评论,但是我的文章太长了。

你的第一个例子日志(“正常运行”)对我来说有点困惑。 只有一个C-DEBUG:AC-DEBUG:B而至少每个C-DEBUG:C都必须有一个,不是吗?

其他例子看起来不错,一切都如我所料( A => B => exception => 1 => 2 => 3 => 4 => A )。 那么,似乎只有一个线程,但例子不知道这是错的; 我看到没有第二个C-DEBUG:A从另一个线程。 你期望什么呢?

关于你的更新:在这里我想知道更多关于你的测试机器的性能,因为每一个异常的抛出都需要一些执行时间。 这就是为什么在循环中抛出异常是一个很大的性能问题。 你的服务器的时间似乎有点慢,但从我的角度来看。

虽然beeing不能给你提示你的问题,但至少我可以给你这样的说法:抛出的异常不是其他线程的阻塞因素。 为了证明我写了一个小程序(见下面的源代码,如果你想知道我是如何做到这一点)。 该程序的输出是

 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线程打印0Thread-1的异常则在callstack上打印。 这里没有阻塞!

这里供参考我的程序:

 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属性检查将大大提高代码的性能。