Microsoft MVP성태의 닷넷 이야기
홈 주인모아 놓은 자료프로그래밍질문/답변사용자 관리 RSS OPML Link
.NET WebAPI 에서 Response 지연되는 이유 [링크 복사], [링크+제목 복사],
조회: 9335
글쓴 사람
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)
4990heyg...5/21/20189317Sybase Adaptive Server Anywhere 6 버전에 대한 질문입니다. [9]
4989강한음5/18/201811517clickonce 배포 후 실행 무응답 [4]
4988C#7....5/17/20188288dynamic 키워드를 사용한 객체 핸들링에 대해서 여쭤보려고 합니다. [1]
4987포플러5/14/20189304닥터왓슨 로그 - c0000005 (액세스 위반) 분석 부탁드려도 될까요? [2]
4986익명5/14/201811009비주얼 스튜디오 wpf 프로젝트에서 어떻게 하면 exe파일과 실행에 필요한 파일들을 분리해서 정리해서 디렉토리로 묶을 수 있을까요? [4]
4985대구개발자5/7/20188568새로운 폴더만 "이름 없는 파일" 오류 [1]
4984안중언5/6/20189266교재 143page [1]
4983익명5/4/201818723(wpf) 다른 컴퓨터에서 사용하면 자꾸 ('CefSharp.Core.dll' 또는 여기에 종속되어 있는 파일이나 어셈블리 중 하나를 로드할 수 없습니다)라고 떠요.ㅠㅠ [5]
4982Soul...4/27/20189654MFC ActiveX 컨트롤 안에 있는 C# ActiveX 컨트롤 포인터 얻기 [4]
4981대전박4/25/20188565WPF IValueConverter 를 구현해서 StaticResource로 사용할때요 [1]
4980대전박4/23/20189738WPF OS버전 따라 Style 적용이 안되는 프로퍼티가 있을수 있나요? [2]
4979초보개발자4/18/201813883C# 프레임워크 버전이 다른 DLL끼리의 사용 [7]파일 다운로드1
4977Soul...4/17/20189011WebBrowser 컨트롤 Script 통신 문제 [3]
4976맹가이버4/14/20189887윈도우 서비스 프로그램에서 응용프로그램 호출하는 법 [1]
4975lemo...4/11/201810675안녕하세요 네이버로그인관련 질문드립니다. [2]
4973홍길동4/6/20188781ebook 출간 계획은 없으신가요? [2]
4978홍길동4/17/20188553    답변글 [답변]: ebook 출간 계획은 없으신가요?
4972dwkim4/3/20189756EasyHook 관련 질문 [4]
4968최홍준3/30/20188522Windows 7 Credential Provider Android와 연동 [1]
4967이대희3/30/20189660비주얼 스튜디오 설치 워크로드 중에 ".NET Core 플랫폼 간 개발" 이건 뭐하는 것인지요. [1]
4965이대희3/30/20188982자마린 설치후 안드로이드 프로젝트 생성시 디자이너가 없다는 에러가 발생합니다. [3]
4969이대희3/31/20189361    답변글 [답변]: 자마린 설치후 안드로이드 프로젝트 생성시 디자이너가 없다는 에러가 발생합니다.파일 다운로드2
4970이대희4/1/20189140        답변글 [답변]: [답변]: 자마린 설치후 안드로이드 프로젝트 생성시 디자이너가 없다는 에러가 발생합니다. [1]
4963이대희3/29/20189707UWP 스터디를 위해 찰스페졸드 저자의 Programming Windows 6판은 어떠한지요? [1]
4962포플러3/26/20189986C# 응용프로그램 (Winform)에서 unhandledexception 발생시 프로그램이 죽는 현상 이외에 재부팅될 수도 있을까요? [2]
4966포플러3/30/20189622    답변글 [답변]: C# 응용프로그램 (Winform)에서 unhandledexception 발생시 프로그램이 죽는 현상 이외에 재부팅될 수도 있을까요? [1]
... 31  32  33  34  [35]  36  37  38  39  40  41  42  43  44  45  ...