на работе мы недавно перенесли набор сервисов из фреймворка 1.1 в фреймворк 3.5.Мы только что импортировали и перекомпилировали старые (1.1) проекты.
Эти службы каждые 7 секунд проверяют БД, собирают ряд задач, которые необходимо выполнить, и для каждой задачи создают поток (используя ThreadPool), который выполняет синхронный (вобъем потока) вызов веб-службы (и некоторые другие вещи).После завершения вызова поток завершается.
Мы создаем новый поток только в том случае, если ThreadPool получил не менее 50% от общего количества доступных потоков (мы используем ThreadPool.GetAvailableThreads, чтобы проверить это).Если это так, поток создается, в противном случае служба подождет секунду (Thread.Sleep (1000);), а затем выполнит новую проверку.
Все это работало нормально в 1.1 и, похоже, все еще работает нормально в 3.5, но только на тестовом компьютере.
Все проблемы, возникшие после выпуска на рабочий компьютер: проверка и потоки выполнены правильно, но вызов веб-службы начинается с огромной задержкой (даже 20 и более минут) иразрешается медленно: в то время как версия 1.1 завершает 3 вызова в секунду (более или менее), версия 3.5 разрешает вызов каждые 20 секунд (и, как уже говорилось, каждый из них с 20-минутной задержкой).Мы не увидели ни проблем с подключением, ни тайм-аутов.
Мы видим, что когда мы запускаем службу, количество потоков (около 30) выделяется за очень короткое время, и каждый из них немедленно запускает вызов WS.(т.е. код выполняет синхронный вызов. ()).Проблема заключается в том, что эти вызовы разрешаются только по одному и через несколько минут после того, как они сделаны.
Теперь: почему это происходит только в рабочей машине?Почему в других тестовых машинах этого не произойдет?
Есть предложения?
Заранее спасибо.
РЕДАКТИРОВАТЬ
Мывнесены некоторые изменения в сервис.Теперь мы разрешаем выделять не более фиксированного количества потоков (35) в пуле потоков.Когда этот номер будет достигнут, служба ожидает завершения потока, прежде чем создавать новый.Процесс работает нормально, но мы по-прежнему замечаем, что каждый веб-запрос выполняется в течение большего промежутка времени:
[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?Почему интервал между вызовом и фактическим соединением растет так сильно?Почему такое поведение происходит только тогда, когда несколько запросов выполняются асинхронно?Это похоже на то, что фреймворк не может выполнить более одного соединения одновременно ...