Microsoft MVP성태의 닷넷 이야기
홈 주인모아 놓은 자료프로그래밍질문/답변사용자 관리 RSS OPML Link
.NET WebAPI 에서 Response 지연되는 이유 [링크 복사], [링크+제목 복사],
조회: 9336
글쓴 사람
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]
... 31  32  33  34  35  36  37  38  39  [40]  41  42  43  44  45  ...
NoWriterDateCnt.TitleFile(s)
4854heyh...7/6/20179662네
4853heyh...7/5/20179766성태님이 작성한대로 해봤습니다. [1]파일 다운로드1
4852김레오7/4/201711874서드파티 dll 디버깅에 대해 질문드립니다. [2]
4851김현준7/3/201711004Datagridview VirtualMode 시 GC가 계속 호출되는 현상이 이해가 안갑니다. [2]
4850heyh...7/3/201710723성태님 밑에 질문드렸던 오류입니다. [1]파일 다운로드1
4849포플러7/2/201729450C#으로 만든 프로그램이 어느 순간 속도가 느려지거나 멈춤현상이 있습니다. [4]
4848윤진영7/2/201712345Microsoft Visual C++ 6.0 무설치 관련 [1]
4847heyh...6/30/201710327아무리 고민해도 답이 안나와서.. 질문 드립니다 [1]
4846heyh...6/28/201710384Clickonce에서 Clickonce로 변수 전달 [1]
4845heyh...6/26/201710055vb.net 에서 manifest 제거 방법 [1]파일 다운로드1
4844san6/21/20179470part3 pdf파일로 보는데 눈아퍼요.... 활자로 보고싶어요 [2]
4843윤현수6/20/20179710socket통신에 관한 질문입니다. [1]
4842오세운6/7/201710397로그인폼 다시 질문드려요. [1]
4841popo6/7/201710170궁금한사항이 있어 질문 드립니다. [1]
4840윤현수6/5/201710173datagridview에 바인딩시킨 dataset.table에 관련된 질문입니다. [2]파일 다운로드1
4839오세운6/2/201711080로그인폼 만들기 [1]
4838후배5/29/201711814PDF Reader 라이브러리.. [3]
4837KDP5/29/201711311c++ to C# 컨버팅 문의 [2]
4836popo5/26/201714450리플렉션 성능 관련 질문 드립니다. [2]
4835guest5/25/201710183wpf Canvas 질문드립니다. [1]
4834부탁드립...5/19/201711100익스체인지 서버 구동중 인증서를 받는 과정에서오류가 납니다 [1]
4833안종윤5/18/201711486winform을 Web Browser에 붙일 수 있는지요? [1]
4832guest5/17/201710982c# UDP socket예제 실행방법 [3]
4831guest5/15/201713456WPF .net 3.5에서 TextBox 한글 문제 [3]
4830초보자5/7/201718353프로그램 비정상 종료 메시지 창 없애는 방법 [4]
4829윤현수4/26/201714742System.Text.Encoding 질문 [1]
... 31  32  33  34  35  36  37  38  39  [40]  41  42  43  44  45  ...