记5.28大促压测的性能优化—线程池相关问题

Posted 2020-09-21

目录：

1.环境介绍

2.症状

3.诊断

4.结论

5.解决

6.对比java实现

废话就不多说了，本文分享下博主在5.28大促压测期间解决的一个性能问题，觉得这个还是比较有意思的，值得总结拿出来分享下。

博主所服务的部门是作为公共业务平台，公共业务平台支持上层所有业务系统（2C、UGC、直播等）。平台中核心之一的就是订单域相关服务，下单服务、查单服务、支付回调服务，当然结算页暂时还是我们负责，结算页负责承上启下进行下单、结算、跳支付中心。每次业务方进行大促期间平台都要进行一次常规压测，做到心里有底。

在压测的上半场，陆续的解决一些不是太奇怪的问题，定位到问题时间都在计划内。下单服务、查单服务、结算页都顺利压测通过。但是到了支付回调服务压测的时候，有个奇怪的问题出现了。

1.环境介绍

我们每年基本两次大促，5.28、双12。两次大促期间相隔时间也就只有半年左右，所以每次大促压测都会心里有点低，基本就是摸底检查下。因为之前的压测性能在这半年期间一般不会出现太大的性能问题。这前提是因为我们每次发布重大的项目的时候都会进行性能压测，所以压测慢慢变得常规化、自动化，遗漏的性能问题应该不会太多。性能指标其实在平时就关注了，而不是大促才来临时抱佛脚，那样其实为时已晚，只能拆东墙补西墙。

应用服务器配置，物理机、32core i7 64位、168g、千兆网卡、压测网络带宽千兆、IIS 7.5、.NET 4.0，这台压测服务器还是很强的。

我们本地会用JMeter进行问题排查。由于这篇文章不是讲怎么做性能压测的，所以其他跟本篇文章关系的不大的情况就不介绍了。包括压测网络隔离、压测机器的配置和节点数等。

我们的要求，顶层服务在200并发下，平均响应时间不能超过50毫秒，TPS要到3000左右。一级服务，也就是最底层服务的要求更高，商品系统、促销系统、卡券系统平均响应时间基本保持在20毫秒以内才能接受。因为一级服务的响应速度直接决定了上层服务的响应速度，这里还要去掉一些其他的调用开销。 

2.症状

这个性能问题的症状还是比较奇怪的，情况是这样的：200并发、2000loop，40w的调用量。一开始前几秒速度是比较快的，基本上TPS到了2500左右。服务器的CPU也到了60左右，还是比较正常的，但是几秒过后处理速度陡降，TPS慢慢在往下掉。从服务器的监控中发现，服务器的CPU是0%消耗。这很吓人，怎么突然不处理了。TPS掉到100多了，显然会一直掉下去。等了大概不到4分钟，一下子CPU又上来了。TPS可以到2000左右。

我们仔细分析查看，首先JMeter的吞吐量的问题，吞吐量是按照你的请求平均响应时间计算的，所以这里看起来TPS是慢慢在减慢其实已经基本停止了。如果你的平均响应时间为20毫秒，那么在单位时间内你的吞吐量是基本可以计算出来的。

症状主要就是这样的，我们接下来对它进行诊断。

3.诊断

开始通过走查代码，看能不能发现点什么。

这是支付回调服务，代码的前后没有太多的业务处理，鉴权检查、订单支付状态修改、触发支付完成事件、调用配送、周边业务通知（这里有一部分需要兼容老代码、老接口）。我们首先主要是查看对外依赖的部分，发现有redis读写的代码，就将redis的部分代码注释掉在进行压测试试看。结果一下子就正常了，这就比较奇怪了，redis是我们其他压测服务共用的，之前压测怎么没有问题。没管那么多了，可能是代码的执行序列不同，在并发领域里面，这也说得通。

我们再通过打印redis执行的时间，看处理需要多久。结果显示，处理速度不均匀，前面的很快，后面的时间都在5-6秒，虽然不均匀但是很有规律。

所以我们都认为是redis的相关问题，就开始一头扎进去检查redis的问题了。开始对redis进行检查，首先是开启Wireshark TCP连接监控，检查链路、redis服务器的Slowlog查看处理时间。redis客户端库的源代码查看（redis客户端排除原生的StackExhange.Redis的有两层封装，一共三层），重点关注有锁的地方和thread wait的地方。同时排查网络问题，再进行压测的时候ping redis服务器看是否有延迟。（此时是晚上21点左右，这个时候的大脑情况大家都懂的。）

就是这样地毯式的搜查，以为是肯定能定位到问题。但是我们却忽视了代码的层次结构，一下子专到了太细节的地方，忽视了整体的架构（指开发架构，因为代码不是我们写的，对代码周边情况不是太了解）。

先看redis服务器的建立情况，tcp抓包查看，连接建立正常，没有丢包，速度也很快。redis的处理速度也没问题，slowlog查看基本get key也就1毫秒不到。（这里需要注意，redis的处理时间还包括队列里等待的时间。slowlog只能看到redis处理的时间，看不到blocking的时间，这里面还包括redis的command在客户端队列的时间。）

所以打印出来的redis处理时间很慢，不纯粹是redis服务器的处理时间，中间有几个环节需要排查的。

经过一番折腾，排查，问题没定位到，已是深夜，精力严重不足了，也要到地铁最后一班车发车时间了，再不走赶不上了，下班回家，上到最后一班地铁没耽误三分钟~~。

重整思路，第二天继续排查。

我们定位到redis客户端的连接是可以先预热的，在global application_begin启动的时候先预热好，然后性能一下子也正常了。

范围进一步缩小，问题出在连接上，这里我们又反思了（一夜觉睡过了，脑子清醒了），那为什么我们之前的压测没出现过这个问题。对技术狂热爱好的我们，哪能善罢甘休。此时问题算是解决了，但是背后所涉及到的相关线索穿不起来，总是不太舒服。（中场休息片刻，已是第二天的下午快傍晚了~~。）技术人员要有这种征服欲，必须搞清楚。

我们开始还原现场，然后开始出大招，开始dump进程文件，分不同的时间段，抓取了几份dump文件down到本地进行分析。

首先查看了线程情况，!runaway，发现大多数线程执行时间都有点长。接着切换到某个线程中~xxs，查看线程调用堆栈。发现在等一把monitor锁。同时切换到其他几个线程中查看下是不是都在等待这把锁。结果确实都在等这把锁。

结论，发现一半的线程都在等待moniter监视器锁，随着时间增加，是不是都在等待这把锁。这比较奇怪。

这把锁是redis库的第三层封装的时候用来lock获取redis connectioin时候用的。我们直接注释掉这把锁，继续压测继续dump，然后又发现一把monitor，这把锁是StackExchange.Redis中的，代码一时半会无法消化，只查了主体代码和周边代码情况，没有时间查看全局情况。（因为时间紧迫）。暂且完全信任第三方库，然后查看redis connection string 的各个参数，是不是可以调整超时时间、连接池大小等。但是还是未能解决。

回过头继续查看dump，查看了下CLR连接池，！ThreadPool，一下子看到问题了。

继续查看其他几个dump文件，Idle都是0，也就是说CLR线程池没有线程来处理请求了，至少CLR线程池的创建速率和并发速率不匹配了。

CLR线程池的创建速率一般是1秒2个线程，线程池的创建速率是否存在滑动时间不太清楚。线程池的大小可以通过 C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Config\machine.config 配置来设置，默认是自动配置的。最小的线程数一般是当前机器的CPU 核数。当然你也可以通过ThreadPool相关方法来设置，ThreadPool.SetMaxThreads(), ThreadPool.SetMinThreads()。

然后我们继续排查代码，发现代码中有用Action的委托的地方，而这个Action是处理异步代码的，上面说的redis的读写都在这个Action里面的。一下我们明白了，所有的线索都连起来了。

4.结论

.NET CLR线程池是共享线程池，也就是说ASP.NET、委托、Task背后都是一个线程池在处理。线程池分为两种，Request线程池、IOCP线程池（完成端口线程池）。

我们现在理下线索：

1.从最开始的JMeter压测吞吐量慢慢变低是个假象，而此时处理已经全面停止，服务器的CPU处理为0%。肉眼看起来变慢是因为请求延迟时间增加了。

2.redis的TCP链路没问题，Wireshark查看没有任何异常、Slowlog没有问题、redis的key comnand慢是因为blocking住了。

3.其他服务压测之所有没问题是因为我们是同步调用redis，当首次TCP连接建立之后速度会上来。

4.Action看起来速度是上去了，但是所有的Action都是CLR线程池中的线程，看起来快是因为还没有到CLR线程池的瓶颈。

Action asyncAction = () =>
           {
               //读写redis
               //发送邮件
               //...

           };

asyncAction();

5.JMeter压测的时候没有延迟，在压测的时候程序没有预热，导致所有的东西需要初始化，IIS、.NET等。这些都会让第一次看起来很快，然后慢慢下降的错觉。

总结：首次建立TCP连接是需要时间的，此时并发过大，所有的线程在wait，wait之后CPU会将这些线程交换出去，此时是明显的所线程上下文切换过程，是一部分开销。当CLR线程池的线程全部耗光吞吐量开始陡降。每次调用其实是开启力了两个线程，一个处理请求的Request，还有一个是Action委托线程。当你以为线程还够的时候，其实线程池已经满了。

5.解决

针对这个问题我们进行了队列化处理。相当于在CLR线程池基础上抽象一个工作队列出来，然后队列的消费线程控制在一定数量之内，初始化的时候默认一个线程，会提供接口创建顶多6个线程。这样当队列的处理速度跟不上的时候可以调用。大致代码如下（已进行适当的修改，非源码模样，仅供参考）：

Service 部分：

private static readonly ConcurrentQueue<NoticeParamEntity> AsyncNotifyPayQueue = new ConcurrentQueue<NoticeParamEntity>();
private static int _workThread;

static ChangeOrderService()
{
    StartWorkThread();
}

public static int GetPayNoticQueueCount()
{
    return AsyncNotifyPayQueue.Count;
}

public static int StartWorkThread()
{
    if (_workThread > 5) return _workThread;

    ThreadPool.QueueUserWorkItem(WaitCallbackImpl);
    _workThread += 1;

    return _workThread;;
}

public static void WaitCallbackImpl(object state)
{
    while (true)
    {
        try
         {
            PayNoticeParamEntity payParam;
            AsyncNotifyPayQueue.TryDequeue(out payParam);

            if (payParam == null)
            {
                Thread.Sleep(5000);
                continue;
            }

            //获取订单详情

            //结转分摊

            //发短信

            //发送消息

            //配送
        }
        catch (Exception exception)
        {
            //log
        }
    }
}

原来调用的地方直接改成入队列：

private void AsyncNotifyPayCompleted(NoticeParamEntity payNoticeParam)
{
    AsyncNotifyPayQueue.Enqueue(payNoticeParam);
}

Controller 代码：

public class WorkQueueController : ApiController
    {
        [Route("worker/server_work_queue")]
        [HttpGet]
        public HttpResponseMessage GetServerWorkQueue()
        {
            var payNoticCount = ChangeOrderService.GetPayNoticQueueCount();

            var result = new HttpResponseMessage()
            {
                Content = new StringContent(payNoticCount.ToString(), Encoding.UTF8, "application/json")
            };

            return result;
        }

        [Route("worker/start-work-thread")]
        [HttpGet]
        public HttpResponseMessage StartWorkThread()
        {
            var count = ChangeOrderService.StartWorkThread();

            var result = new HttpResponseMessage()
             {
                Content = new StringContent(count.ToString(), Encoding.UTF8, "application/json")
            };

            return result;
        }
    }

上述代码是未经过抽象封装的，仅供参考。思路是不变的，将线程利用率最大化，延迟任务无需占用过多线程，将CPU密集型和IO密集型分开。让速度不匹配的动作分开。

优化后的TPS可以到7000，比原来快近三倍。

6.对比JAVA实现

这个问题其实如果在JAVA里也许不太容易出现，JAVA的线程池功能是比较强大的，并发库比较丰富。在JAVA里两行代码就可以搞定了。

ExecutorService fiexdExecutorService = Executors.newFixedThreadPool(Thread_count);

直接构造一个指定数量的线程池，当然我们也可以设置线程池的队列类型、大小、包括队列满了之后、线程池满了之后的拒绝策略。这些用起来还是比较方便的。