예기치 않은 동작이 직장에서 .NET 1.1에서 3.5

Question

로 마이그레이션 한 후 우리는 최근 프레임 워크 3.5 프레임 워크 1.1 서비스 세트를 마이그레이션. 방금 이전 (1.1) 프로젝트를 가져 와서 다시 컴파일했습니다.

이러한 서비스는 매 7 초마다 DB를 확인하고 각 작업마다 동기식 (스레드 범위에서) 웹 서비스 호출 (및 다른 일부 작업)을 만드는 스레드를 만듭니다 (ThreadPool 사용) . 호출이 완료되면 스레드가 완료됩니다.

우리는 ThreadPool이 가능한 총 스레드의 50 % 이상을 가지고있는 경우에만 새 스레드를 생성 (우리는 그것을 확인 ThreadPool.GetAvailableThreads를 사용). 그래서, 스레드가 생성되면, 그렇지 않으면 서비스는 초 (Thread.sleep를 (1000)) 기다린 후 새로운 체크를합니다.

이 모든

는 있지만 시험 기계, 1.1에서 잘 작동하고 여전히 3.5에서 잘 작동하는 것 같다.

모든 문제는 프로덕션 시스템에 한 번 릴리스되었습니다. 검사 및 스레드는 올바르게 완료되었지만 웹 서비스 호출은 막대한 지연 (심지어 20 분 이상)으로 시작되어 천천히 해결됩니다. 1.1 버전은 3 (상기와 같이 20 분 지연으로 이들 각각을하고) (어느 정도) 초당 호출 3.5 버전이 호출마다 20 초 해결. 연결 문제 나 시간 초과가 발생하지 않았습니다.

서비스를 시작할 때 매우 짧은 시간에 여러 개의 스레드 (약 30 개)가 할당되며 각 스레드는 즉각적으로 WS 호출을 시작합니다. 즉 코드가.() 동기 호출을 실행합니다. 문제는 그 전화가 한 번에 한 번만 해결되고 몇 분 후에는 해결된다는 것입니다. 이제

이 생산 기계에만 일어나는 이유는 무엇입니까? 왜 다른 테스트 머신에서는 이것이 일어나지 않을까요?

의견이 있으십니까?

미리 감사드립니다.

EDIT 우리는 서비스의 일부 변경했습니다. 이제 스레드 풀에 고정 된 수의 스레드 (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 

또한 검사는 약 20 초에 마지막으로 효과적인 TCP 통화 것을 증명하지만, 체 후 단 몇 분을 수행 : 프로세스 잘 작동하지만, 우리는 여전히 각 웹 요청이 더 큰 시간 범위에서 수행되는 것을 알 수 코드 호출. 예를 들어

다음 코드 : 59 : 56,039, 12 완료 : 00 : 17,404

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 만 이루어진다을 생산할

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 사이에는 어떤 현상이 발생합니까? 통화와 실제 연결 사이의 간격이 너무 길어지는 이유는 무엇입니까? 비동기 적으로 많은 요청이 수행 될 때만이 동작이 발생하는 이유는 무엇입니까? 그것은 프레임 워크가 한 번에 둘 이상의 연결을 수행 할 수없는 것과 같습니다 ...

Answer 1

마침내 우리는 프록시 (시스템 관리자가 누가이 프록시를 누가 또는 왜 구성했는지 알 수 없음)로 인한 문제를 발견했습니다.

이 프록시는 서비스처럼 시스템으로 실행되는 프로세스에서만 활성화됩니다. 테스트에 사용되는 작은 응용 프로그램과 같이 사용자로 실행되는 프로세스는이 프록시를 사용하지 않으므로 서비스가 여러 가지 문제로 실행되는 동안 작은 테스트 응용 프로그램이 정상적으로 실행됩니다.

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

Answer 2

a) ThreadPool의 알고리즘과 한계가 변경되었습니다. AvailableThreads/2를 사용하는 접근 방식은 한 번 작동했을 수도 있지만 Win7 노트북에서는 1023/2와 500 Threads가 너무 많습니다.

b) 스레드와 ThreadPool을보고 있지만 설명에서 네트워크 또는 방화벽 문제 일 수 있습니다.