ASP.NET WebAPI 在初始阶段响应缓慢

【问题标题】：ASP.NET WebAPI slow responses at the initial phaseASP.NET WebAPI 在初始阶段响应缓慢
【发布时间】：2019-01-08 17:22:52
【问题描述】：

我创建了一个仅引用 Web API 的空项目，并调整了这些简单的 API，以查看其中一个异步作业是否存在任何性能差异以及任何可能的挂起。

public class TestController : ApiController
{
    [HttpGet]
    [Route("Welcome")]
    public async Task<string> Welcome()
    {
        string r = await SlowMethod();
        return r;
    }

    public async Task<string> SlowMethod()
    {
        Thread.Sleep(3000);
        return await Task.FromResult("data");
    }

    [HttpGet]
    [Route("WelcomeSync")]
    public string WelcomeSync()
    {
        string r = SlowSyncMethod();
        return r;
    }

    public string SlowSyncMethod()
    {
        Thread.Sleep(3000);
        return "data";
    }
}

我使用带有this test plan 的jMeter 运行API 测试。结果在吞吐量方面几乎相同，但在 jMeter 的这个结果表中的“Max”项有显着差异。

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

Max 是毫秒单位。由于Thread.Sleep(3000); 的结果，每个 API 每个请求至少需要 3 秒，但其中一个请求或其中一些请求需要 32 秒才能完成。

这是否意味着至少有一个异步作业挂起？如果有，导致挂起的罪魁祸首是什么？

更新

我曾经怀疑异步作业的挂起行为，但事实证明并非如此。只需更改测试顺序即可得出相同的结果。 第一次测试在测试开始时总是很慢。这与异步与同步作业完全无关。

无论如何，我尝试使用Stopwatch 将日志留在SlowMethod(); 之间，以查看异步方法是否实际挂起，很快我发现异步和同步API 都没有挂起。日志总是打印“花了 3 秒”。 

2018-08-12 13:40:11 "Welcome async 'Welcome'. It took 3 seconds"
2018-08-12 13:40:14 "Welcome async 'Welcome'. It took 3 seconds"
2018-08-12 13:40:17 "Welcome async 'Welcome'. It took 3 seconds"
.
.
.

迟到的是 HTTP 响应本身。缓慢有一个明显的特征。

  • 表演很快就开始失去节奏。
  • 它一直在减速，直到达到 30~40 秒的处理速度
  • 之后它开始从拖拽的表演中恢复过来。
  • 最终它在 3 秒内一直响应直到结束。

这是可以帮助您更好地描绘的日志。

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: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: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 
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 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"

IIS recompilation、IIS application pool recycling 和 IIS idle timeout 设置是主要嫌疑人，但事实证明它们与此问题无关。到底是什么原因？

【问题讨论】：

    标签： iis asp.net-web-api async-await task


    【解决方案1】：

    虽然在同步测试中使用Thread.Sleep(3000); 是可以的，但在伪造长时间运行的异步调用时使用Task.Delay 将获得更好的表示。

    public async Task<string> SlowMethod() {
    await Task.Delay(3000);
    return "data";
}

    【讨论】：

      【解决方案2】：

      罪魁祸首

      我终于打开了引擎盖并尝试检查可能导致此性能问题的每一个小细节。问题在于ThreadPool。好吧，从现在开始，它似乎不再是问题了。

      ThreadPool 的本质是不喜欢创建新线程并增加其池中的线程数并且在适用时倾向于回退到最小线程数是幕后情况这种现象。

      在我的环境中，ThreadPool 以 4 个线程开始。我能够通过调用实现这一点。

      ThreadPool.GetMinThreads(out int threadCount, out int portThread);

      在初始阶段只有 4 个线程 根本不足以在 jMeter 测试期间处理大量传入的 HTTP 请求。因此，让ThreadPool 维护至少 200 个线程以便它可以从 200 个线程开始就解决了这个问题。

      ThreadPool.SetMinThreads(200, 4);

      现在每个请求都将在 3 秒内按预期处理，直到测试结束。但不建议以无意义的方式操作ThreadPool 中的最小线程数，因为这可能会影响应用程序的性能。

      这是MSDN的警告

      默认情况下，最小线程数设置为系统上的处理器数。您可以使用 SetMinThreads 方法来增加最小线程数。但是，不必要地增加这些值可能会导致性能问题。如果同时启动太多任务，所有任务都可能看起来很慢。在大多数情况下，线程池使用自己的分配线程算法会表现得更好。将最小值减少到少于处理器数量也会损害性能。

      不使用SetMinThreads的简单解决方案

      使用Task.Delay(3000);而不是Thread.Sleep(3000) 也解决了这个问题。由于Thread.Sleep(3000) 只是阻塞了当前线程，可能会导致ThreadPool 创建更多线程。实际上，您可以在资源监视器中看到这实际发生的情况。

      这是Task.Delay(3000); 版本，我在测试开始后 1 分钟截取了这张截图。仅创建了 59 个线程，并且该数量在测试期间保持不变或低于。

      这是Thread.Sleep(3000); 版本，我同时拍了这个。但 iisexpress 已产生 116 个线程，并且在测试期间该数量不断增加。

      【讨论】：

        猜你喜欢
        • 1970-01-01
        • 2021-03-25
        • 1970-01-01
        • 2014-02-04
        • 2012-05-23
        • 1970-01-01
        • 1970-01-01
        • 1970-01-01
        • 1970-01-01
        相关资源
        最近更新 更多
        热门标签
        Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode