multithreading - 创建 BackgroundWorkers 的线程似乎将 Completed 事件排队

Question

我注意到 BackgroundWorkers 的一些奇怪行为以及它们正在触发的事件，其中事件似乎在一个线程中排队，而实际上并未使用 CPU。

基本上系统的设计是，基于用户交互，创建一个线程来发送 Web 请求以获取一些数据。根据结果​​，它可能会触发许多其他异步请求，对每个请求使用 BackgroundWorkers。我这样做是因为管理请求的代码使用锁来确保一次只发送一个请求(以避免向服务器发送多个同时请求的垃圾邮件，可能导致服务器忽略/阻止它们)。可能有更好的设计，我很想听听(我对 C#/Windows 窗体编程比较陌生，可以使用这些建议)。但是，无论设计更改如何，我都有兴趣了解导致我所看到的行为的原因。

我编写了一个相对简单的测试应用程序来演示这个问题。它基本上只是一个带有按钮和文本框的表单来显示结果(您可能可以不使用表单并在控制台上显示结果，但我这样做是为了复制我的实际应用程序所做的事情)。这是代码:

delegate void AddToLogCallback(string str);

private void AddToLog(string str)
{
    if(textBox1.InvokeRequired)
    {
        AddToLogCallback callback = new AddToLogCallback(AddToLog);
        Invoke(callback, new object[] { str });
    }
    else
    {
        textBox1.Text += DateTime.Now.ToString() + "   " + str + System.Environment.NewLine;
        textBox1.Select(textBox1.Text.Length, 0);
        textBox1.ScrollToCaret();
    }
}

private void Progress(object sender, ProgressChangedEventArgs args)
{
    AddToLog(args.UserState.ToString());
}

private void Completed(object sender, RunWorkerCompletedEventArgs args)
{
    AddToLog(args.Result.ToString());
}

private void DoWork(object sender, DoWorkEventArgs args)
{
    BackgroundWorker worker = sender as BackgroundWorker;
    lock (typeof(Form1)) // Ensure only a single request at a time
    {
        worker.ReportProgress(0, "Start");
        Thread.Sleep(2000); // Simulate waiting on the request
        worker.ReportProgress(50, "Middle");
        Thread.Sleep(2000); // Simulate handling the response from the request
        worker.ReportProgress(100, "End");
        args.Result = args.Argument;
    }
}

private void button1_Click(object sender, EventArgs e)
{
    Thread thread = new Thread(RunMe);
    thread.Start();
}

private void RunMe()
{
    for(int i=0; i < 20; i++)
    {
        AddToLog("Starting " + i.ToString());
        BackgroundWorker worker = new BackgroundWorker();
        worker.WorkerReportsProgress = true;
        worker.DoWork += DoWork;
        worker.RunWorkerCompleted += Completed;
        worker.ProgressChanged += Progress;
        worker.RunWorkerAsync(i);
    }
}

这是我回来的结果:

30/07/2009 2:43:22 PM   Starting 0
30/07/2009 2:43:22 PM   Starting 1
<snip>
30/07/2009 2:43:22 PM   Starting 18
30/07/2009 2:43:22 PM   Starting 19
30/07/2009 2:43:23 PM   Start
30/07/2009 2:43:36 PM   Middle
30/07/2009 2:43:36 PM   End
30/07/2009 2:43:36 PM   0
30/07/2009 2:43:36 PM   Start
30/07/2009 2:43:36 PM   Middle
30/07/2009 2:43:36 PM   End
30/07/2009 2:43:36 PM   1
30/07/2009 2:43:36 PM   Start
30/07/2009 2:43:36 PM   Middle
30/07/2009 2:43:36 PM   End
30/07/2009 2:43:36 PM   8
30/07/2009 2:43:36 PM   Start
30/07/2009 2:43:36 PM   Middle
30/07/2009 2:43:38 PM   13
30/07/2009 2:43:38 PM   End
30/07/2009 2:43:38 PM   Start
30/07/2009 2:43:40 PM   Middle
30/07/2009 2:43:42 PM   18
30/07/2009 2:43:42 PM   Start
30/07/2009 2:43:42 PM   End
30/07/2009 2:43:44 PM   Middle
30/07/2009 2:43:46 PM   End
30/07/2009 2:43:46 PM   2
30/07/2009 2:43:46 PM   Start
30/07/2009 2:43:48 PM   Middle

如您所见，在显示第一条“开始”消息后有 13 秒的延迟，之后它会处理大约 15 条消息(尽管大多数消息被触发之间有 2 秒的延迟)。

有谁知道发生了什么？

Answer 1

编辑:好的，我从头开始。这是一个简短但完整的控制台应用程序，它显示了问题。它记录消息的时间和它所在的线程:

using System;
using System.Threading;
using System.ComponentModel;

class Test
{
    static void Main()
    {
        for(int i=0; i < 20; i++)
        {
            Log("Starting " + i);
            BackgroundWorker worker = new BackgroundWorker();
            worker.WorkerReportsProgress = true;
            worker.DoWork += DoWork;
            worker.RunWorkerCompleted += Completed;
            worker.ProgressChanged += Progress;
            worker.RunWorkerAsync(i);
        }
        Console.ReadLine();
    }

    static void Log(object o)
    {
        Console.WriteLine("{0:HH:mm:ss.fff} : {1} : {2}",
            DateTime.Now, Thread.CurrentThread.ManagedThreadId, o);
    }

    private static void Progress(object sender,
                                 ProgressChangedEventArgs args)
    {
        Log(args.UserState);
    }

    private static void Completed(object sender,
                                  RunWorkerCompletedEventArgs args)
    {
        Log(args.Result);
    }

    private static void DoWork(object sender, DoWorkEventArgs args)
    {
        BackgroundWorker worker = (BackgroundWorker) sender;
        Log("Worker " + args.Argument + " started");
        lock (typeof(Test)) // Ensure only a single request at a time
        {
            worker.ReportProgress(0, "Start");
            Thread.Sleep(2000); // Simulate waiting on the request
            worker.ReportProgress(50, "Middle");
            Thread.Sleep(2000); // Simulate handling the response
            worker.ReportProgress(100, "End");
            args.Result = args.Argument;
        }
    }
}

样本输出:

14:51:35.323 : 1 : Starting 0
14:51:35.328 : 1 : Starting 1
14:51:35.330 : 1 : Starting 2
14:51:35.330 : 3 : Worker 0 started
14:51:35.334 : 4 : Worker 1 started
14:51:35.332 : 1 : Starting 3
14:51:35.337 : 1 : Starting 4
14:51:35.339 : 1 : Starting 5
14:51:35.340 : 1 : Starting 6
14:51:35.342 : 1 : Starting 7
14:51:35.343 : 1 : Starting 8
14:51:35.345 : 1 : Starting 9
14:51:35.346 : 1 : Starting 10
14:51:35.350 : 1 : Starting 11
14:51:35.351 : 1 : Starting 12
14:51:35.353 : 1 : Starting 13
14:51:35.355 : 1 : Starting 14
14:51:35.356 : 1 : Starting 15
14:51:35.358 : 1 : Starting 16
14:51:35.359 : 1 : Starting 17
14:51:35.361 : 1 : Starting 18
14:51:35.363 : 1 : Starting 19
14:51:36.334 : 5 : Worker 2 started
14:51:36.834 : 6 : Start
14:51:36.835 : 6 : Worker 3 started
14:51:37.334 : 7 : Worker 4 started
14:51:37.834 : 8 : Worker 5 started
14:51:38.334 : 9 : Worker 6 started
14:51:38.836 : 10 : Worker 7 started
14:51:39.334 : 3 : Worker 8 started
14:51:39.335 : 11 : Worker 9 started
14:51:40.335 : 12 : Worker 10 started
14:51:41.335 : 13 : Worker 11 started
14:51:42.335 : 14 : Worker 12 started
14:51:43.334 : 4 : Worker 13 started
14:51:44.335 : 15 : Worker 14 started
14:51:45.336 : 16 : Worker 15 started
14:51:46.335 : 17 : Worker 16 started
14:51:47.334 : 5 : Worker 17 started
14:51:48.335 : 18 : Worker 18 started
14:51:49.335 : 19 : Worker 19 started
14:51:50.335 : 20 : Middle
14:51:50.336 : 20 : End
14:51:50.337 : 20 : Start
14:51:50.339 : 20 : 0
14:51:50.341 : 20 : Middle
14:51:50.343 : 20 : End
14:51:50.344 : 20 : 1
14:51:50.346 : 20 : Start
14:51:50.348 : 20 : Middle
14:51:50.349 : 20 : End
14:51:50.351 : 20 : 2
14:51:50.352 : 20 : Start
14:51:50.354 : 20 : Middle
14:51:51.334 : 6 : End
14:51:51.335 : 6 : Start
14:51:51.334 : 20 : 3
14:51:53.334 : 20 : Middle

(ETC)

现在试图弄清楚发生了什么......但重要的是要注意工作线程的启动时间间隔为 1 秒。

编辑:进一步调查:如果我调用 ThreadPool.SetMinThreads(500, 500)然后即使在我的 Vista 盒子上，它也显示 worker 基本上都是一起开始的。

如果您尝试上述程序，无论是否调用 SetMinThreads，您的盒子会发生什么情况？ ?如果它在这种情况下有帮助，但对您的实际程序没有帮助，您能否制作一个类似的简短但完整的程序，表明即使使用 SetMinThreads 仍然是一个问题称呼？

我相信我明白了。我认为 ReportProgress正在添加一个新的 ThreadPool处理消息的任务......同时，您正忙于向线程池添加 20 个任务。现在关于线程池的事情是，如果没有足够的线程可以在请求到达时立即为它提供服务，那么池会在创建新线程之前等待半秒。这是为了避免为一组请求创建大量线程，如果您只是等待现有任务完成，这些请求可以很容易地在一个线程上处理。

因此，在 10 秒内，您只是将任务添加到长队列并每半秒创建一个新线程。 20 个“主要”任务都是相对较长的，而 ReportProgress任务非常短——所以只要你有足够的线程来处理所有长时间运行的请求和一个短的请求，你就离开了，所有的消息都会很快通过。

如果您将调用添加到

ThreadPool.SetMaxThreads(50, 50);

在这一切开始之前，您会看到它的行为与您期望的一样。我并不是建议您必须为您的实际应用程序这样做，而只是为了显示差异。这会在池中创建一堆线程开始，只是等待请求。

对您的设计的一条评论:您在不同的线程上有 20 个不同的任务，但实际上一次只能发生一个(由于锁定)。无论如何，您都在有效地序列化请求，那么为什么要使用多个线程呢？我希望您的实际应用程序没有这个问题。