Microsoft MVP성태의 닷넷 이야기
.NET Framework: 369. ThreadPool.QueueUserWorkItem의 실행 지연 [링크 복사], [링크+제목 복사]
조회: 14391
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일

ThreadPool.QueueUserWorkItem의 실행 지연

최근에 아주 재미있는 질문을 하나 봤습니다. ^^

동적 background workers 생성 시간 지연 발생 이슈
; http://social.msdn.microsoft.com/Forums/ko-KR/visualcsharpko/thread/59f6af80-2903-44b0-8f07-e3c78029a246/

질문을 다시 한번 정리해 보면, 다음과 같이 BackgroundWorker 객체를 생성했을 때,

using System;
using System.ComponentModel;
using System.Windows.Forms;
using System.Threading;
using System.Diagnostics;

namespace WindowsFormsApplication1
{
    public partial class Form1 : Form
    {
        public Form1()
        {
            InitializeComponent();
        }

        private void Form1_Load(object sender, EventArgs e)
        {
            for (int i = 0; i < 20; i++)
            {
                BackgroundWorker bgw = new BackgroundWorker();
                bgw.DoWork += new DoWorkEventHandler(bgw_DoWork);
                bgw.WorkerSupportsCancellation = true;
                bgw.RunWorkerAsync(DateTime.Now);
            }
        }

        void bgw_DoWork(object sender, DoWorkEventArgs e)
        {
            DateTime started = (DateTime)e.Argument;
            TimeSpan elapsed = DateTime.Now - started;

            Trace.WriteLine(Thread.CurrentThread.ManagedThreadId + ": Work started after " + elapsed);
            Thread.Sleep(1000 * 60);
        }
    }
}

이를 실행시켜 보면, BackgroundWorker.RunWorkerAsync 호출 후 bgw_DoWork가 호출되기까지 지연시간이 있음을 확인할 수 있습니다.

16: Work started after 00:00:00.0231812
11: Work started after 00:00:00.0231812
13: Work started after 00:00:00.0231812
14: Work started after 00:00:00.0231812
12: Work started after 00:00:00.0231812
6: Work started after 00:00:00.0241812
10: Work started after 00:00:00.0231812
15: Work started after 00:00:00.0231812
17: Work started after 00:00:01.0011160
18: Work started after 00:00:01.5013938
19: Work started after 00:00:02.0026778
20: Work started after 00:00:02.4813795
21: Work started after 00:00:02.9821267
22: Work started after 00:00:03.4832162
23: Work started after 00:00:03.9835948
24: Work started after 00:00:04.4842889
25: Work started after 00:00:04.9850062
26: Work started after 00:00:05.9859442
27: Work started after 00:00:06.9870558
28: Work started after 00:00:07.9884043

보는 바와 같이 위의 실행 결과에서 15번 스레드까지는 빠르게 bgw_DoWork가 호출되는 반면 그 이후로는 1초 이상의 지연이 누적되면서 발생하고 있습니다. 오~~~ 재미있지 않나요? ^^

더욱 재미있는 것은 bgw_DoWork 메소드에 포함된 Thread.Sleep(1000 * 60); 코드를 제거하면 저런 현상이 없다는 점입니다.

// Thread.Sleep(1000 * 60); 코드를 제거했을 때의 실행 결과
10: Work started after 00:00:00.0009996
11: Work started after 00:00:00.0330125
6: Work started after 00:00:00.0019996
...[생략: 모든 결과가 밀리초 내에서 실행]...
16: Work started after 00:00:00.1193636
12: Work started after 00:00:00.0079991




BackgroundWorker는 내부적으로 DoWork의 실행을 닷넷의 기본 스레드 풀을 이용해 실행합니다. 따라서, 위의 현상은 BackgroundWorker에 한정된 것이 아니고 ThreadPool.QueueUserWorkItem을 이용해서도 재현할 수 있습니다.

for (int i = 0; i < 20; i++)
{
    DateTime started = DateTime.Now;

    ThreadPool.QueueUserWorkItem(
        (obj) =>
        {
            TimeSpan elapsed = DateTime.Now - (DateTime)obj;
            Trace.WriteLine(Thread.CurrentThread.ManagedThreadId + ": Work started after " + elapsed);

            Thread.Sleep(1000 * 60);
        }, started);
}

다음은 실행 결과입니다.

12: Work started after 00:00:00.0070009
10: Work started after 00:00:00.0040013
15: Work started after 00:00:00.0140017
13: Work started after 00:00:00.0060018
14: Work started after 00:00:00.0140017
6: Work started after 00:00:00.0029826
11: Work started after 00:00:00.0040013
16: Work started after 00:00:00.0140017
17: Work started after 00:00:01.0021976
18: Work started after 00:00:01.5034076
19: Work started after 00:00:02.0042271
20: Work started after 00:00:02.5047204
21: Work started after 00:00:03.0050134
22: Work started after 00:00:03.5056883
23: Work started after 00:00:04.0073806
24: Work started after 00:00:04.5074312
25: Work started after 00:00:05.0083132
26: Work started after 00:00:06.0105310
27: Work started after 00:00:07.0122110
28: Work started after 00:00:08.0123949

정말 ^^ BackgroundWorker와 실행 지연 현상이 유사하게 나타나는 것을 확인할 수 있고, 마찬가지로 Sleep 코드를 뺀 경우의 결과도 유사합니다. 좀더 확대해서 테스트 해보면, .NET 4.0의 Task도 ThreadPool을 기반으로 하기 때문에 마찬가지 현상이 발생합니다.

for (int i = 0; i < 20; i++)
{
    DateTime started = DateTime.Now;

    Task.Factory.StartNew((obj) =>
    {
        TimeSpan elapsed = DateTime.Now - (DateTime)obj;
        Trace.WriteLine(Thread.CurrentThread.ManagedThreadId + ": Work started after " + elapsed);

        Thread.Sleep(1000 * 60);
    }, started);
}

그런데, 왜 이런 현상이 나타나는 것일까요? 알 수 없습니다. ^^ 마이크로소프트의 내부 직원만이 이에 대해 정확한 답을 할 수 있겠지요.

단지, 예상해 볼 수 있는 것은 ThreadPool의 용도가 단타성 용도로 적합하고 스레드를 늘리는 것에 신중(!)하다는 점입니다. ThreadPool에 있는 모든 스레드가 점유되었을 때 빠르게 스레드의 수를 늘리기 보다는 가능한 기존 스레드의 재활용을 하려고 노력한다는 것인데요. 따라서, 해당 작업이 장시간 소요되는 것(Time-consuming operations)이라면 ThreadPool을 이용하기 보다는 Thread 객체를 만들어 사용하는 것이 더 효율적입니다.

하지만, 아이러니하게도 BackgroundWorker는 UI 반응성을 떨어뜨리지 않기 위해 장시간 소요되는 작업을 맡기는 용도로 만들어진 것이기 때문에 ThreadPool의 동작과 어울리지 않고, 오히려 내부적으로 개별 Thread를 만들어서 처리해야 하지 않았을까... 하는 생각이 듭니다. 또는 마이크로소프트 측에서 설마 BackgroundWorker를 이렇게 많이 사용하리라고는 짐작하지 못했을 수도 있고.




어쨌든, 문제가 ThreadPool과 연관이 있다는 것을 알았다면 해결책도 나온 것이나 다름없습니다. 실행 결과를 보면, 대략 처음 8개의 DoWork 메소드는 빠르게 실행되다가 이후부터 느려지는 것을 목격하게 되는데요. 왜 하필 8개일까요? ^^

그 이유는, ThreadPool이 기본적으로 유지하는 최소 스레드가 수가 8개이기 때문입니다.

int workerT, portT;
ThreadPool.GetMinThreads(out workerT, out portT);

Trace.WriteLine(string.Format("Min: worker - {0}, port - {1}", workerT, portT));
// 출력 결과
// Min: worker - 8, port - 8

아하~~~ 그럼 기본 스레드 수를 응용 프로그램에서 예상되는 최대치 언저리로 만들어주면 되겠군요. 예를 들어 이 글의 예제에서는 20개가 사용되었으니까, 다음과 같은 식으로 해주면 해결이 됩니다.

int workerT, portT;
int minRequire = 25; // 다른 용도로도 사용될 수 있으므로 안전하게 +5

ThreadPool.GetMinThreads(out workerT, out portT);

if (workerT < minRequire)
{
    int inc = minRequire - workerT;
    workerT += inc;
}

ThreadPool.SetMinThreads(workerT, portT);

이렇게 SetMinThreads를 호출하고 나면 ThreadPool.QueueUserWorkItem, Task.Factory.StartNew, BackgroundWorker의 모든 수행 결과가 개선되는 것을 확인할 수 있습니다.

10: Work started after 00:00:00.0129996
13: Work started after 00:00:00.0200018
14: Work started after 00:00:00.0260009
...[생략: 모든 결과가 밀리초 내에서 실행]...
16: Work started after 00:00:00.0470040
15: Work started after 00:00:00.0300031
12: Work started after 00:00:00.0330018

첨부된 파일은 위의 결과를 테스트 해볼 수 있는 간단한 프로젝트입니다.

(그나저나... IT 분야에서도 "닥터 하우스"에 나오는 것처럼 "진단학과"가 있었으면 좋겠군요. ^^)




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]

[연관 글]


donaricano-btn



[최초 등록일: ]
[최종 수정일: 7/2/2020 ]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:techsharer at outlook.com

비밀번호

댓글 쓴 사람
 



2013-06-04 12시48분
[ing™] 제가 알고 있기로는 ThreadPool이 기본적으로 유지하는 최소 스레드가 수는 현재 CPU의 특성에 따라 다르게 되는 것으로 알고 있습니다. CPU Core(하이퍼쓰레드 포함) 갯수대로 초기 스레드가 수가 결정이 된답니다.
[손님]
2013-06-04 01시10분
넵. ^^ 이 글의 테스트 결과에 의하면, CPU Core(HT포함)수만큼 초기 스레드가 결정되고 그것을 초과해서 요구했을 때 0.5 초마다 CPU Core(HT포함)수만큼 생성되다가, 다시 그 수를 넘으면 1초마다 생성되는 규칙이 있는 것 같습니다. (CPU Core수만큼의 규칙대로 0.5초씩 늘어나는 것 같기도 하고요.)
혹시, 이런 규칙이 설명된 공식 문서가 어디 있는지 아시나요?

정성태
2013-07-17 11시50분
[ing™] 스택에서 본건 있지만 공식 문서가 어디에 있는지는 저도 잘 모르겠습니다.
그리고 여러가지로 테스트를 해 본결과 쓰레드풀에서는 기본적으로 재 사용을 하지만 쓰레드 안에 Waiting 하는(DB Query or Sleep, HTTPClient load) 작업이 1초이상 걸리면 새로운 쓰레드를 생성하고 있습니다.
[손님]
2015-11-03 01시04분
이와 관련된 WCF에서의 현상을 다음의 질문에서 볼 수 있습니다.

BottleNeck/delay when Calling WCF service
; http://stackoverflow.com/questions/33402316/bottleneck-delay-when-calling-wcf-service/
정성태

[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
12687정성태6/22/202119오류 유형: 729. Invalid data: Invalid artifact, java se app service only supports .jar artifact
12686정성태6/21/202143Java: 22. Azure - 자바(Java)로 만드는 Web App Service
12685정성태6/21/202152Java: 21. Azure Web App Service에 배포된 Java 프로세스의 메모리 및 힙(Heap) 덤프 뜨는 방법
12684정성태6/19/202141오류 유형: 728. Visual Studio 2022부터 DTE.get_Properties 속성 접근 시 System.MissingMethodException 예외 발생
12683정성태6/18/202165VS.NET IDE: 166. Visual Studio 2022 - Windows Forms 프로젝트의 x86 DLL 컨트롤이 Designer에서 오류가 발생하는 문제파일 다운로드1
12682정성태6/18/202173VS.NET IDE: 165. Visual Studio 2022를 위한 Extension 마이그레이션
12681정성태6/18/202153오류 유형: 727. .NET 2.0 ~ 3.5 + x64 환경에서 System.EnterpriseServices 참조 시 CS8012 경고
12680정성태6/18/202140오류 유형: 726. python2.7.exe 실행 시 0xc000007b 오류
12679정성태6/18/202196COM 개체 관련: 23. CoInitializeSecurity의 전역 설정을 재정의하는 CoSetProxyBlanket 함수 사용법파일 다운로드1
12678정성태6/17/202176.NET Framework: 1072. C# - CoCreateInstance 관련 Inteop 오류 정리파일 다운로드1
12677정성태6/17/202175VC++: 144. 역공학을 통한 lxssmanager.dll의 ILxssSession 사용법 분석파일 다운로드1
12676정성태6/16/202195VC++: 143. ionescu007/lxss github repo에 공개된 lxssmanager.dll의 CLSID_LxssUserSession/IID_ILxssSession 사용법파일 다운로드1
12675정성태6/16/202149Java: 20. maven package 명령어 결과물로 (war가 아닌) jar 생성 방법
12674정성태6/15/202193VC++: 142. DEFINE_GUID 사용법
12673정성태6/15/202153Java: 19. IntelliJ - 자바(Java)로 만드는 Web App을 Tomcat에서 실행하는 방법
12672정성태6/15/202142오류 유형: 725. IntelliJ에서 Java webapp 실행 시 "Address localhost:1099 is already in use" 오류
12671정성태6/15/202156오류 유형: 724. Tomcat 실행 시 Failed to initialize connector [Connector[HTTP/1.1-8080]] 오류
12670정성태6/13/202169.NET Framework: 1071. DLL Surrogate를 이용한 Out-of-process COM 개체에서의 CoInitializeSecurity 문제파일 다운로드1
12669정성태6/11/2021157.NET Framework: 1070. 사용자 정의 GetHashCode 메서드 구현은 C# 9.0의 record 또는 리팩터링에 맡기세요.
12668정성태6/11/2021167.NET Framework: 1069. C# - DLL Surrogate를 이용한 Out-of-process COM 개체 제작파일 다운로드2
12667정성태6/10/202199.NET Framework: 1068. COM+ 서버 응용 프로그램을 이용해 CoInitializeSecurity 제약 해결파일 다운로드1
12666정성태6/10/202177.NET Framework: 1067. 별도 DLL에 포함된 타입을 STAThread Main 메서드에서 사용하는 경우 CoInitializeSecurity 자동 호출파일 다운로드1
12665정성태6/9/2021145.NET Framework: 1066. Wslhub.Sdk 사용으로 알아보는 CoInitializeSecurity 사용 제약파일 다운로드1
12664정성태6/9/2021101오류 유형: 723. COM+ PIA 참조 시 "This operation failed because the QueryInterface call on the COM component" 오류
12663정성태6/9/2021130.NET Framework: 1065. Windows Forms - 속성 창의 디자인 설정 지원: 문자열 목록 내에서 항목을 선택하는 TypeConverter 제작파일 다운로드1
[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...