从 .NET 1.1 迁移到 3.5 后出现意外行为答案

【问题标题】：Unexpected behaviour after migrating from .NET 1.1 to 3.5从 .NET 1.1 迁移到 3.5 后出现意外行为
【发布时间】：2011-08-05 08:19:31
【问题描述】：

在工作中，我们最近将一组服务从框架 1.1 迁移到框架 3.5。我们刚刚导入并重新编译了旧 (1.1) 项目。

这些服务每 7 秒检查一次数据库，选择一些要执行的任务，并为每个任务创建一个线程（使用 ThreadPool）进行同步（在线程范围内）Web 服务调用（以及其他一些事情）。调用完成后线程就完成了。

仅当 ThreadPool 获得至少 50% 的可用线程时，我们才创建一个新线程（我们使用 ThreadPool.GetAvailableThreads 来检查）。如果是，则创建线程，否则服务等待一秒钟 (Thread.Sleep(1000);)，然后进行新的检查。

所有这些在 1.1 中运行良好，在 3.5 中似乎仍然运行良好，但仅在测试机器上运行。

一旦发布到生产机器，所有问题就开始了：检查和线程都正确完成，但是 Web 服务调用开始时有很大的延迟（甚至 20 分钟或更长时间）并且解决缓慢：而 1.1 版本完成 3 调用每秒（或多或少），3.5 版本每 20 秒解析一次呼叫（并且如前所述，每个呼叫都有 20 分钟的延迟）。我们没有看到任何连接问题或超时。

我们看到的是，当我们启动服务时，在非常短的时间内分配了多个线程（大约 30 个），每个线程都立即启动 WS 调用（即代码执行 .() 同步调用）。问题在于，这些呼叫一次只能解决一个，并且在拨打后几分钟。

现在：为什么这只发生在生产机器上？为什么在其他测试机器上不会发生这种情况？

有什么建议吗？

提前致谢。

编辑

我们对服务进行了一些更改。现在我们最多允许在线程池中分配固定数量的线程（35）。当达到这个数字时，服务会在创建新线程之前等待线程完成。该过程运行良好，但我们仍然注意到每个 Web 请求都在更大的时间跨度内执行：

[11:48:40,365] [  336] INFO  MyClass.Call(): Time elapsed: 00:04:07.0172059
[11:49:14,771] [ 3052] INFO  MyClass.Call(): Time elapsed: 00:04:41.4236761
[11:49:27,256] [ 3928] INFO  MyClass.Call(): Time elapsed: 00:04:53.9081310
[11:49:51,303] [ 5444] INFO  MyClass.Call(): Time elapsed: 00:05:17.9551599
[11:50:34,787] [ 5332] INFO  MyClass.Call(): Time elapsed: 00:06:00.2054303
[11:50:55,366] [ 4672] INFO  MyClass.Call(): Time elapsed: 00:06:19.7211802
[11:51:15,288] [ 1248] INFO  MyClass.Call(): Time elapsed: 00:06:38.6588014
[11:51:34,975] [ 4168] INFO  MyClass.Call(): Time elapsed: 00:06:57.3307959
[11:53:00,429] [ 5224] INFO  MyClass.Call(): Time elapsed: 00:08:18.7531920
[11:53:18,367] [  908] INFO  MyClass.Call(): Time elapsed: 00:08:35.7064255
[11:53:44,398] [ 3616] INFO  MyClass.Call(): Time elapsed: 00:09:00.7222106
[11:54:04,523] [ 6108] INFO  MyClass.Call(): Time elapsed: 00:09:19.8942083
[11:54:29,523] [ 5536] INFO  MyClass.Call(): Time elapsed: 00:09:43.8943619
[11:54:47,242] [ 5048] INFO  MyClass.Call(): Time elapsed: 00:10:00.5819687
[11:55:05,992] [ 3756] INFO  MyClass.Call(): Time elapsed: 00:10:18.3164572
[11:55:26,508] [ 4628] INFO  MyClass.Call(): Time elapsed: 00:10:37.8322071
[11:55:52,493] [ 5812] INFO  MyClass.Call(): Time elapsed: 00:11:02.8167420
[11:56:22,305] [ 5752] INFO  MyClass.Call(): Time elapsed: 00:11:32.0356790
[11:56:31,680] [ 4688] INFO  MyClass.Call(): Time elapsed: 00:11:41.0513617
[11:57:00,556] [ 5844] INFO  MyClass.Call(): Time elapsed: 00:12:08.8952899
[11:57:10,759] [ 5760] INFO  MyClass.Call(): Time elapsed: 00:12:18.0203483
[11:57:49,321] [ 5684] INFO  MyClass.Call(): Time elapsed: 00:12:35.3017089
[11:57:59,056] [ 5920] INFO  MyClass.Call(): Time elapsed: 00:12:26.9110302

进一步检查表明，有效的 TCP 调用持续约 20 秒，但仅在 che 代码调用后几分钟执行。

例如下面的代码：

slg.Info("Beginning connection.");

DateTime callStart = DateTime.Now;

odOutput = ws_Proxy.WSMethod(odInput);;

log.InfoFormat("Time elapsed: {0}", DateTime.Now - callStart);

制作此日志

[11:47:59,396] [ 5468] INFO  MyClass.Call(): Beginning connection.
[12:00:17,026] [ 5468] INFO  MyClass.Call(): Time elapsed: 00:12:17.6297208

但 TCP 连接仅在 11:59:56,039 建立并在 12:00:17,404 完成

11:59:56.0399905 TCP Connect    SUCCESS Length: 0, mss: 1300, sackopt: 4, tsopt: 0, wsopt: 0, rcvwin: 64240, rcvwinscale: 0, sndwinscale: 0, connid: 2254643208, seqnum: 155953480  0
11:59:56.8962917 TCP Send...    SUCCESS Length: 302, startime: 1012803, endtime: 1012811, connid: 2254643208, seqnum: 0 0
11:59:56.9794909 TCP Receive    SUCCESS Length: 2, connid: 2254643208, seqnum: 0    0
11:59:57.7751084 TCP Send...    SUCCESS Length: 625, startime: 1012806, endtime: 1012820, connid: 2254643208, seqnum: 0 0
11:59:57.7751656 TCP Receive    SUCCESS Length: 2, connid: 2254643208, seqnum: 0    0
12:00:08.3723058 TCP Receive    SUCCESS Length: 1300, connid: 2254643208, seqnum: 0 0
12:00:16.5336435 TCP Unknown    SUCCESS Length: 0, connid: 2254643208, seqnum: 0    0
12:00:16.5337723 TCP Receive    SUCCESS Length: 1265, connid: 2254643208, seqnum: 0 0
12:00:17.4046865 TCP Disconnect SUCCESS Length: 0, connid: 2158355531, seqnum: 4133859281   0

在 11:47:59,396 和 11:59:56,039 之间会发生什么？为什么通话和实际连接之间的间隔会增长这么多？为什么只有在异步执行多个请求时才会发生这种行为？这就像框架一次无法执行多个连接......

【问题讨论】：

因为它是生产。
我发现很难准确理解您的代码在做什么。你能写一个简短但完整的程序来演示这个问题吗？您很可能会发现这样做，您自己解决了问题。
生产机和测试机有什么硬件差异？
您的编辑不会获得太多浏览量。最好尽可能隔离问题并提出新问题。

标签： c# .net multithreading web-services service

【解决方案1】：

a) ThreadPool 的算法和限制发生了变化。您使用 AvailableThreads/2 的方法可能曾经奏效，但在我的 Win7 笔记本电脑上，1023/2 和 500 线程太多了。

b) 您正在查看线程和线程池，但根据您的描述，它也可能是网络或防火墙问题。

【讨论】：

a) 我已经限制了可用线程的数量，但没有任何改变。 b) 如果是这样，我无法解释为什么仍在使用 1.1 框架。
好吧，也许 1.1 库使用的 API 略有不同。或者很久以前有人在你的防火墙中配置了一些东西。您需要分析网络上发生的事情，这看起来不像是线程问题。

【解决方案2】：

最后我们发现这个问题似乎是由代理引起的（系统管理员无法判断是谁或为什么配置了这个代理）。

此代理仅由作为系统运行的进程（如服务）激活。以用户身份运行的进程（如用于测试的小应用程序）不使用此代理，这就是为什么小测试应用程序运行正常而服务运行时出现许多问题的原因。

我们解决了这个问题，只需在服务配置中添加以下几行：

<system.net>
  <defaultProxy enabled="false" />
</system.net>

【讨论】：