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);
}
그런데, 왜 이런 현상이 나타나는 것일까요? 알 수 없습니다. ^^ 마이크로소프트의 내부 직원만이 이에 대해 정확한 답을 할 수 있겠지요. (혹은, 직접 BCL 코드를 분석해 보시면 됩니다.)
단지, 예상해 볼 수 있는 것은 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 (Environment.ProcessorCount에 해당)
아하~~~ 그럼 기본 스레드 수를 응용 프로그램에서 예상되는 최대치 언저리로 만들어주면 되겠군요. 예를 들어 이 글의 예제에서는 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 분야에서도 "
닥터 하우스"에 나오는 것처럼 "진단학과"가 있었으면 좋겠군요. ^^)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]