Microsoft MVP성태의 닷넷 이야기
홈 주인모아 놓은 자료프로그래밍질문/답변사용자 관리 RSS OPML Link
.NET WebAPI 에서 Response 지연되는 이유 [링크 복사], [링크+제목 복사]
조회: 9152
글쓴 사람
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]
... 16  17  18  19  20  21  22  23  24  25  26  27  28  29  [30]  ...
NoWriterDateCnt.TitleFile(s)
5125게스트2/19/20196930delegate를 활용한 event 를 적절히 불러오고 싶습니다. [2]
5124정근화2/12/20196806윈도우 서버2003 환경 오류 [2]
5123김주현2/8/20196839MS LUIS 에 대한 소개 하실 계획이 있으신가요? [1]
5122jaka...2/1/20198687Clickonce 배포 후 Command 실행 [2]파일 다운로드1
5121엔벌이1/31/20198110C# DataGridView의 MDB파일 함수? ArrayList？ [1]파일 다운로드1
5120임우진1/30/20198605웹에서 응용프로그램 바로 실행하기 관련 브라우저에서 파라미터가 넘어오지 않습니다.ㅜㅜ [2]
5119guest1/29/201910001교재에 오탈자 있어 알려드리려 합니다 [1]
5118WPF꿈...1/26/20197926GetHashCode 메서드에 대해서 [1]
5117하주형1/25/20198597List<int>에 대한 이해가 잘안됩니다. [5]
5116게스트1/24/20197350asp.net 관련 gridview webform 질문 드립니다. [1]파일 다운로드1
5115Soul...1/24/20197472투명 패널 질문드립니다. [2]
5114박현일1/20/20197820WPF DataContext 관련 초보 질문을 드려봅니다.^^ [5]
5113하주형1/20/20197119안녕하세요 시작하세요 C# 인코딩관련 질문드립니다. [1]
5112손성배1/19/201916107안녕하세요 cp949 인스톨시 오류입니다... 너무 힘들어요 [5]
5111게스트1/10/20197757암호화 라이센스 관련 문의 드립니다. [1]
5110WPF꿈...1/9/20197403Thread Abort 함수 사용시 [2]
5109닷넷개발1/9/20197373thread 관련 질문 예제.. [2]파일 다운로드1
5108닷넷개발1/9/20198521thread 관련 질문 드립니다.. [4]
5107우코아1/4/201911176WPF에서 로딩중 이미지를 구현 - Project [5]파일 다운로드1
5106우코아1/3/20198811WPF에서 로딩중 이미지를 구현 - Source [1]
5104우코아1/1/201910043WPF에서 로딩중 이미지를 구현 [4]
5103이혜성12/31/20181063132bit .net 으로 만들어진 dll파일 [5]
5102돌고래12/18/20189404자료구조와 알고리즘 도서 관련 질문입니다. [4]
5101세퉁12/17/20187725안녕하세요 wpf 공부중인데 질문있습니다. [4]파일 다운로드1
5100돌고래12/16/20187091도서 추천 부탁드립니다. [1]
5099WPF12/12/201810172안녕하세요. WPF에서 UWP Control을 참조하려고 합니다. [3]파일 다운로드1
... 16  17  18  19  20  21  22  23  24  25  26  27  28  29  [30]  ...