記5.28大促壓測的效能優化—執行緒池相關問題
目錄：
1.環境介紹
2.症狀
3.診斷
4.結論
5.解決
6.對比java實現
廢話就不多說了，本文分享下博主在5.28大促壓測期間解決的一個性能問題，覺得這個還是比較有意思的，值得總結拿出來分享下。
博主所服務的部門是作為公共業務平臺，公共業務平臺支援上層所有業務系統（2C、UGC、直播等）。平臺中核心之一的就是訂單域相關服務，下單服務、查單服務、支付回撥服務，當然結算頁暫時還是我們負責，結算頁負責承上啟下進行下單、結算、跳支付中心。每次業務方進行大促期間平臺都要進行一次常規壓測，做到心裡有底。
在壓測的上半場，陸續的解決一些不是太奇怪的問題，定位到問題時間都在計劃內。下單服務、查單服務、結算頁都順利壓測通過。但是到了支付回撥服務壓測的時候，有個奇怪的問題出現了。
1.環境介紹
我們每年基本兩次大促，5.28、雙12。兩次大促期間相隔時間也就只有半年左右，所以每次大促壓測都會心裡有點低，基本就是摸底檢查下。因為之前的壓測效能在這半年期間一般不會出現太大的效能問題。這前提是因為我們每次釋出重大的專案的時候都會進行效能壓測，所以壓測慢慢變得常規化、自動化，遺漏的效能問題應該不會太多。效能指標其實在平時就關注了，而不是大促才來臨時抱佛腳，那樣其實為時已晚，只能拆東牆補西牆。
應用伺服器配置，物理機、32core、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.BeginInvoke();
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);
直接構造一個指定數量的執行緒池，當然我們也可以設定執行緒池的佇列型別、大小、包括佇列滿了之後、執行緒池滿了之後的拒絕策略。這些用起來還是比較方便的。