Microsoft MVP성태의 닷넷 이야기
홈 주인모아 놓은 자료프로그래밍질문/답변사용자 관리 RSS OPML Link
.NET WebAPI 에서 Response 지연되는 이유 [링크 복사], [링크+제목 복사],
조회: 9645
글쓴 사람
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]
... 46  47  48  49  50  [51]  52  53  54  55  56  57  58  59  60  ...
NoWriterDateCnt.TitleFile(s)
1556김응규4/22/201512517    답변글 [답변]: WCF net.tcp 관련해서 질문 드립니다. [1]파일 다운로드1
1554(삭제)4/19/201513286안드로이드 에뮬레이터에서 특정 앱 구동불가할때! [2]
1552spow...4/18/201519165마이크로세컨드 단위의 Sleep이 필요한데 찾질 못하겠습니다. [5]
1553spow...4/18/201512486    답변글 [답변]: 마이크로세컨드 단위의 Sleep이 필요한데 찾질 못하겠습니다. [1]
1551인디언기...4/16/201511852iisnode에 대해서 글 올리셨던데 질문이 있습니다 [1]
1549김선아4/15/201512323.net framework 4.5와 c++ dll에 관한 질문입니다 [1]
1550김선아4/15/201510730    답변글 [답변]: .net framework 4.5와 c++ dll에 관한 질문입니다 [2]
1547문명식4/3/201512764IWebBrowser Key Event 관련 [2]
1545나종식3/25/201511738internet explorer dns cache flush [2]
1543이용원3/23/201511691hyper-v 질문드려요! [1]
1544이용원3/24/201510849    답변글 한가지만 더 여쭤볼게요! [1]
1541임기성3/20/201518067Microsoft.Office.Core dll관련 문제 [1]
1539펜플3/17/201511407asp.net 질문입니다. [1]
1540113/17/201511374    답변글 [답변]: asp.net 질문입니다. [1]
1538열공합시닷3/13/201512147중계서버 질문드립니다 [1]
1537김재영3/11/201513235asp.net의 빌드 유휴시간 이후의 리빌드 작업을 컨트롤 할 수 있습니까? [2]
1536솔솔3/9/201511682mac address얻으려고 하는데요.. [1]
1535Stud...3/4/201512259C#엔 MFC의 theApp 과 같은 기능을 하는것이 없나요? [3]
1534김동진3/4/201511683C#에서 BHO로 Windows Explorer에서의 동작이 가능할지요 [2]
1533김동현3/3/201512018컴파일 된 프로그램에 코드 삽입(?) 관련입니다. [1]
1532반가워요3/3/201514616C# 소켓연결에 packet송수신... [8]
1531강현수3/2/201513263C# com 등록 시 GUID 변경 관련 문의 [1]
1529김민규2/15/201513157C++ 64bit/32bit [3]파일 다운로드1
1528김개똥2/14/201510672좀 관련없는 질문이지만, 정말 답답하고 찾는데 명확한 해답 찾지못해 질문 올립니다. <Windows 사용자 인증> [1]
1527방문자1/27/201511688System Timer의 Tick에서 Backgroundworker를 호출하면 스레드 문제가 있을까요? [1]
1526황상대1/26/201513545C# 마샬링 관련 질문이 있습니다. [1]
... 46  47  48  49  50  [51]  52  53  54  55  56  57  58  59  60  ...