Microsoft MVP성태의 닷넷 이야기
홈 주인모아 놓은 자료프로그래밍질문/답변사용자 관리 RSS OPML Link
.NET WebAPI 에서 Response 지연되는 이유 [링크 복사], [링크+제목 복사],
조회: 12464
글쓴 사람
david
홈페이지
첨부 파일
 

안녕하세요.

약 보름 동안 이 문제의 원인을 규명하려고 애썼는데,
도저히 제가 가진 지식 수준이나 분석 능력으로는 원인 규명이 불가능하여 실례 무릎쓰고 질문을 남깁니다.

매우 간단한 프로젝트 ( https://drive.google.com/file/d/1YgFLdWmB-cVSb6HLcFLgfm_R1Bunn2cq/view?usp=sharing ) 이니,
코드를 먼저 봐주시고 아래 질문 내용을 봐주시면 무엇을 질문하고 싶은지 바로 아실 것 같습니다.
테스트코드는 굳이 돌려보지 않으셔도, 아래 로그데이터를 참고해주시면 어떤 현상인지 대충 아실거라 생각됩니다.
하지만 직접 돌려보시는게 더 좋긴 좋을 것 같네요...



■ 질문 요약

    - 첨부 프로젝트는 .NET WebAPI 이다. ( https://drive.google.com/file/d/1YgFLdWmB-cVSb6HLcFLgfm_R1Bunn2cq/view?usp=sharing )
    - 해당 WebAPI 실행 환경은 VisualStudio2017 을 통해 "디버깅 시작" 으로 iisexpress 상에서 구동시킨 것이다.
    - 동봉된 Async.jmx jMeter 테스트 플랜이 있다.
    - 그것을 실행해보면 Max 항목에서 응답을 받기까지 몇 십초가 걸리는 경우가 있는데....

         -> 질문 1. " 왜 3초만에 응답을 줘야하는 코드에서 그렇게까지 늦게 Response 를 주는 것인지 정확한 원인을 알고 싶다. "
         -> 질문 2. " 요청이 시작되는 초반에만 3초, 4초, 5초 ... 몇 십초까지 점차적으로 응답이 느려졌다가, 특정 최대 수치를 찍은 후에는 30초, 29초, 28초, 27초 .... 3초 로 서서히 성능이 정상화 된다. 왜 요청이 시작된 초반에만 이런 것일까? "
         -> 질문 3. " JetBrain DotTrace 를 통해서 CLR Worker 를 보니 Thread.Waiting 상태로 42초 동안있었던 것을 볼 수 있었는데, 왜 그렇게 오랫동안 Waiting 상태로 있는 것인지? "



[참고 테스트 결과]

※ 언뜻 테스트 결과만 보면 Async 와 Sync 의 차이점으로 보이지만, 테스트 순서를 바꿔도, 첫 번째 수행하는 테스트에서 Max 수치가 높아지는 현상은 동일합니다.
※ IIS 의 소스 컴파일, WorkerThread 재사용 문제는 아닌 것 같습니다.

========================================================================================================================================
Label Samples Average Min Max Std.Dev Error% Throughput Received KB/sec Sent KB/sec Avg.Bytes

Async 100000 3193 3000 [32046] 1343.6219321793749 0.0 62.534550339062335 21.557320575868168 7.69468099875181 353.0
Sync 100000 3003 3000 [3050] 3.523236520886259 0.0 66.54055014396047 23.458143165986066 8.447530779994983 361.0
========================================================================================================================================




[참고 로그]

※ 위 질문 요약 내용에서 언급하였듯, Request 후 Response 를 받기까지 시간이 점진적으로 늘어났다가, 점진적으로 최초 의도한 3초까지 떨어집니다.
※ 3초까지 떨어진 이후에는 지속적으로 3초 리턴 성능을 유지합니다. ( 그래서 후에 실행되는 테스트는 async 이던 sync 이던 오래걸리는 경우가 나오지 않음 )
========================================================================================================================================
2018-08-04 04:48:50.030 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 3. The result was "data"
2018-08-04 04:48:50.030 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 3. The result was "data"
2018-08-04 04:48:50.030 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 3. The result was "data"
2018-08-04 04:48:50.030 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 3. The result was "data"
2018-08-04 04:48:50.632 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 4. The result was "data"
2018-08-04 04:48:51.637 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 5. The result was "data"
2018-08-04 04:48:52.631 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 6. The result was "data"
2018-08-04 04:48:52.968 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 6. The result was "data"
2018-08-04 04:48:52.969 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 6. The result was "data"
2018-08-04 04:48:52.969 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 6. The result was "data"
2018-08-04 04:48:52.973 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 6. The result was "data"
2018-08-04 04:48:53.631 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 7. The result was "data"
2018-08-04 04:48:53.637 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 7. The result was "data"
2018-08-04 04:48:54.631 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 8. The result was "data"
2018-08-04 04:48:54.640 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 8. The result was "data"
2018-08-04 04:48:55.633 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 9. The result was "data"
2018-08-04 04:48:55.635 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 9. The result was "data"
2018-08-04 04:48:55.975 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 9. The result was "data"
2018-08-04 04:48:55.976 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 9. The result was "data"
2018-08-04 04:48:55.976 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 9. The result was "data"
2018-08-04 04:48:55.979 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 9. The result was "data"
2018-08-04 04:48:56.633 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 10. The result was "data"
2018-08-04 04:48:56.636 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 10. The result was "data"
2018-08-04 04:48:56.642 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 10. The result was "data"
2018-08-04 04:48:57.629 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 11. The result was "data"
2018-08-04 04:48:57.632 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 11. The result was "data"
2018-08-04 04:48:57.641 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 11. The result was "data"
2018-08-04 04:48:58.635 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:58.639 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:58.641 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:58.980 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:58.985 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:58.986 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:58.986 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 12. The result was "data"
2018-08-04 04:48:59.631 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 13. The result was "data"
2018-08-04 04:48:59.636 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 13. The result was "data"
2018-08-04 04:48:59.640 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 13. The result was "data"
2018-08-04 04:48:59.646 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 13. The result was "data"
2018-08-04 04:49:00.632 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 14. The result was "data"
2018-08-04 04:49:00.633 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 14. The result was "data"
2018-08-04 04:49:00.636 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 14. The result was "data"
2018-08-04 04:49:00.647 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 14. The result was "data"
2018-08-04 04:49:01.636 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.639 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.643 +09:00 [INF] CurrentThread 9, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.645 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.985 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.987 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.993 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:01.998 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 15. The result was "data"
2018-08-04 04:49:02.634 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 16. The result was "data"
2018-08-04 04:49:02.635 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 16. The result was "data"
2018-08-04 04:49:02.639 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 16. The result was "data"
2018-08-04 04:49:02.644 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 16. The result was "data"
2018-08-04 04:49:02.649 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 16. The result was "data"
2018-08-04 04:49:03.635 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 17. The result was "data"
2018-08-04 04:49:03.637 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 17. The result was "data"
2018-08-04 04:49:03.638 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 17. The result was "data"
2018-08-04 04:49:03.641 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 17. The result was "data"
2018-08-04 04:49:03.652 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 17. The result was "data"
2018-08-04 04:49:04.639 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.641 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.643 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.647 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.650 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.994 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.994 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.998 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:04.999 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 18. The result was "data"
2018-08-04 04:49:05.633 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 19. The result was "data"
2018-08-04 04:49:05.636 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 19. The result was "data"
2018-08-04 04:49:05.640 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 19. The result was "data"
2018-08-04 04:49:05.643 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 19. The result was "data"
2018-08-04 04:49:05.646 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 19. The result was "data"
2018-08-04 04:49:05.652 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 19. The result was "data"
2018-08-04 04:49:06.633 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 20. The result was "data"
2018-08-04 04:49:06.638 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 20. The result was "data"
2018-08-04 04:49:06.641 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 20. The result was "data"
2018-08-04 04:49:06.643 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 20. The result was "data"
2018-08-04 04:49:06.647 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 20. The result was "data"
2018-08-04 04:49:06.655 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 20. The result was "data"
2018-08-04 04:49:07.635 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.642 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.646 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.647 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.651 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.654 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.997 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:07.998 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:08.003 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:08.008 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 21. The result was "data"
2018-08-04 04:49:08.636 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:08.639 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:08.644 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:08.649 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:08.653 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:08.654 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:08.657 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 22. The result was "data"
2018-08-04 04:49:09.634 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:09.637 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:09.643 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:09.646 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:09.647 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:09.650 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:09.658 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:10.639 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:10.640 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 23. The result was "data"
2018-08-04 04:49:10.647 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:10.652 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:10.654 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:10.655 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:10.658 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:11.002 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:11.003 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:11.008 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:11.009 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:11.634 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:11.641 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:11.644 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:11.649 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:11.654 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:11.656 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:11.657 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:11.662 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:12.632 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:12.636 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:12.640 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:12.645 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:12.649 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:12.650 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:12.652 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:12.661 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:13.632 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.642 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.644 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.650 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.656 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.657 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.657 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:13.662 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.007 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.008 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.015 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.020 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.637 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.641 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:14.649 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:14.651 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:14.656 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:14.658 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:14.661 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:14.662 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:14.665 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:15.631 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:15.634 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:15.639 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:15.644 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:15.648 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:15.652 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:15.653 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:15.655 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:15.665 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:16.635 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:16.638 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:16.647 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:16.650 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:16.669 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:16.669 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:16.669 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:16.670 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:16.673 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.014 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.015 +09:00 [INF] CurrentThread 15, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.020 +09:00 [INF] CurrentThread 15, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.021 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.632 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.640 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.644 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.651 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.654 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.660 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.662 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 30. The result was "data"
2018-08-04 04:49:17.668 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:17.675 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:17.676 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.634 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.644 +09:00 [INF] CurrentThread 10, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.647 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.648 +09:00 [INF] CurrentThread 15, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.651 +09:00 [INF] CurrentThread 15, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.654 +09:00 [INF] CurrentThread 15, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.661 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 31. The result was "data"
2018-08-04 04:49:18.668 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:18.671 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:18.675 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:19.640 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:19.646 +09:00 [INF] CurrentThread 11, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:19.646 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:19.656 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:19.659 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 32. The result was "data"
2018-08-04 04:49:19.667 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:19.669 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:19.673 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:19.677 +09:00 [INF] CurrentThread 15, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:19.679 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 29. The result was "data"
2018-08-04 04:49:20.016 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 28. The result was "data"
2018-08-04 04:49:20.017 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.023 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.028 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.634 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.637 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.645 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.649 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 27. The result was "data"
2018-08-04 04:49:20.656 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:20.659 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 26. The result was "data"
2018-08-04 04:49:20.667 +09:00 [INF] CurrentThread 12, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:20.668 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:20.673 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:20.675 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:20.682 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:21.638 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:21.641 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:21.645 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:21.647 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 25. The result was "data"
2018-08-04 04:49:21.654 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:21.658 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
2018-08-04 04:49:21.662 +09:00 [INF] CurrentThread 16, Context LeaseLifeTimeServiceProperty, Time passed 24. The result was "data"
.
.
.
2018-08-04 05:03:11.422 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 3. The result was "data"
2018-08-04 05:03:14.492 +09:00 [INF] CurrentThread 14, Context LeaseLifeTimeServiceProperty, Time passed 3. The result was "data"
.
.
.
========================================================================================================================================


이상입니다.
어떻게 질문을 간결하게 할까,
필요한 정보는 다 전달되었나 고민 많이 하면서 작성했는데
답변하는데 필요한 정보가 누락된 것이 없었으면 좋겠네요.

이 현상은 Thread.Sleep(3000); 이 아니라,
Task.Delay(3000) 으로 주면 방지할 수 있긴 합니다만...
Thread.Sleep 을 했을 때 왜 그렇게까지 느리게 Response 를 받게되는 것인지 정말 궁금합니다...

저도 답변 받을 때 까지 최대한 파고들어가볼 것입니다.

미리 감사의 말씀 남깁니다.
감사합니다.






[최초 등록일: ]
[최종 수정일: 8/19/2018]

비밀번호
댓글 작성자
 


2018-08-19 03시02분
일단 다음의 글에 따라 변경을 해보고 결과를 좀 알려주세요.

ThreadPool.QueueUserWorkItem 의 실행 지연
; http://www.sysnet.pe.kr/2/0/1455
정성태
2018-08-19 05시25분
[david] 동일한 이슈네요. 컨트롤러 생성할 때 ThreadPool.SetMinThreads(200, 8); 으로 맞춰주고나니
균일하게 3초로 리턴을 해주네요. 정말 감사합니다.

그리고 왜 요청이 4개씩 처리되는지도 궁금했었는데, ThreadPool GetMinThread 를 보니 4개가 설정되어있더라구요.

정말 감사합니다 드디어 궁금증이 풀렸네요 ㅠㅠ
[guest]
2018-08-19 05시42분
[david] 정말 기분 좋네요 너무 궁금했었는데... ㅠ
정말 대단하신 것 같습니다.. 다시 한 번 감사드려요
[guest]
... [76]  77  78  79  80  81  82  83  84  85  86  87  88  89  90  ...
NoWriterDateCnt.TitleFile(s)
635박희진4/27/200712389스마트클라이언트 위로 DIV가 못올라오고 스마트 클라이언트 뒤로 숨는 현상 [1]
632해운대끓...4/23/200710887이전에 소개 되었던 확장 매서드 아티클을 읽고 생각나는 의문 [1]
620이방은4/18/200713013질문있어요.. [2]
619탑6/17/200712195Child Form 에서 Mdi Form 의 메소드 Access 방법 [1]
616김우정4/15/200714854CAS 보안설정을 위한 ActiveX 관련 질문입니다 [2]파일 다운로드1
614박성희4/13/200711530IE Embedded된 스마트클라이언트로 로그인 정보를 보내려면 어떻게 해야 되나요? [2]
612김성헌4/11/200714125Vista, ShellExecute(,"runas",) 문제 [1]
611탑~4/10/200711066페이지 치고 들어가는거 막기... [2]
606한귀순4/3/200711423combobox usercontrol [2]
604채영사랑3/29/200711729<질문> System.Runtime.InteropServices.COMException: 개체가 필요합니다. [2]
603근바이3/28/200711227솔루션 -> 구성관리자 [1]
602김성헌3/27/200711486ActiveX 브로커 모듈과 통신방법은 RPC ??
607정성태4/4/200713364    답변글 [답변]: ActiveX 브로커 모듈과 통신방법은 RPC ??
601엔틱스3/22/200711371자동 로그인의 궁금증 [1]
600창민이3/16/200714434ATL 동적조회 관하여... [2]파일 다운로드1
597ygso...3/14/200710866단순 무식한 궁금증.. [1]
596조빵3/14/200711078SmartClient로 사용자PC의 엑셀을 실행시킬수는 없나요? [1]
594ygso...3/13/200711421ClickOnce를 이용하여 SmartClient를 배포할경우.. [2]
589김희택3/2/200710698리소스 추가 방법에 대한 아티클을 보던중에 질문요... [1]파일 다운로드1
588이성진2/24/200712925웹 -> 스마트클라이언트 -> 웹서비스 의 세션 공유 방법 ? [1]
583김영민2/22/200711316Vista에서 "관리자 권한으로 실행"을 통해 실행한 프로세스의 동작
584정성태2/22/200712728    답변글 [답변]: Vista에서 "관리자 권한으로 실행"을 통해 실행한 프로세스의 동작
582한귀순2/22/200711333sqlhelper 의 updatedataset
585정성태2/23/200710639    답변글 [답변]: sqlhelper 의 updatedataset [1]
579futu...2/16/200712107VS2005의 스마트 클라이언트에서 웹브라우저 예제 질문입니다. [1]
578정해봉2/16/200711333IE Embeded Assambly 방식에서 CAS 설정 방법 [1]
... [76]  77  78  79  80  81  82  83  84  85  86  87  88  89  90  ...