Parallel.For翻船事件剖析－使用Concurrency Visualizer

網友Loops留言分享了一段程式：使用Parallel.For進行平行運算，原本測試平行運算速度勝過循序運算，卻迴圈加入一行Console.WriteLine("{0}", index)後情勢逆轉，跑得比循序迴圈還慢！

直覺推測此一現象肇因於Console為共用資源，多執行緒同時存取時涉及資源鎖定、協調同步、Context Switch等運作機制，衍生額外計算及IO。當平行處理邏輯複雜度不高，這些額外成本抵消掉平行處理的效益，甚至弊大於利，最終導致執行效率比循序處理還差。這點在用.NET展現多核威力(1) - 從ThreadPool翻船談起 一文曾印證過。

我將Loops的程式簡化，抽掉數學運算，只保留Console.WriteLine，簡化以便驗證Parallel.For執行15,000次Console.WriteLine()比直接跑For迴圈來得慢。在我的i7 2600執行約為870ms vs 620ms，慢了40％左右。

using System;

using System.Collections.Generic;

using System.Threading.Tasks;

using System.Diagnostics;

using System.Collections.Concurrent;

namespace TPL

{

    public class Program

    {

        static List<string> Results = new List<string>();

        public static void Main(string[] args)

        {

            RunTest(false);

            Console.WriteLine("Result:");

            foreach (var s in Results)

            {

                Console.WriteLine(s);

            }

        }

        static void RunTest(bool parallel)

        {

            int totalNum = 15000;

            Stopwatch timer = new Stopwatch();

            timer.Reset();

            timer.Start();

            if (parallel)

            {

                Parallel.For(0, totalNum,

                    (i, state) =>

                    {

                        Console.WriteLine("{0}", i);

                    });

            }

            else

            {

                for (int i = 0; i < totalNum; i++)

                {

                    Console.WriteLine("{0}", i);

                }

            }

            timer.Stop();

            Results.Add(string.Format(

                "TEST Parallel: {1}, Duration = {0:N0}ms",

                timer.ElapsedMilliseconds,

                parallel ? "Y" : "N"));

        }

    }

}

這又是一起「Parallel.For（多執行緒）陰溝翻船」事件，不難猜想與Context Switch、Lock、Wait等機制有關。但是，面對多執行緒的疑難雜症，難道我們永遠只能靠想像、揣模、猜想求解，無法「讓數據說話」、「有圖有真相」嗎？

這回我發現一個好工具－Concurrency Visualizer，專門為平行作業程式提供類似Visual Studio效能分析工具的監測及分析功能，是偵察多執行緒效能議題的神兵利器！

透過Visual Studio下載安裝：

之後Analyze選單會多出一個Concurrency Visualizer項目：

Concurrency Visualizer的運作原理與Visual Studio效能分析工具相似：啟動.NET程式後，依固定時間間隔取樣，記錄當下正在執行的程式碼位置。程式結束後統計結果，出現次數愈多，代表該部分執行較耗時，多半就是瓶頸所在。而Concurrency Visualizer被設計用來偵察多工作業程式，能提供從Thread、CPU Core角度蒐集的資訊，以利剖析多執行緒程式效能問題。

我使用Start with Current Project選項執行前述的TPL測試專案，分別RunTest(true)及RunTest(false)測試Parallel.For及單純For迴圈。由分析報告可明顯看出二者的CPU使用率差異，對Parallel.For效能較差的原因，也有了較明確的推論依據。

先看For的CPU使用狀況，850ms左右的執行時間，只有一個CLR Worker Thread，且幾乎都是Logical Core 1一核獨忙：（開啟Concurrency Visualizer側錄取會影響效能，執行時間比原先的620ms久）

Parallel.For有八個System.Threading.Tasks，產生八條CLR Worker Thread，充分利用i7的八個邏輯處理器，八核齊揚，但時間卻得花上1.4秒：

來看時間花在哪裡?

For的主要時間花在System.IO._ConsoleStream.Write()，即Console.WriteLine()實做的輸出邏輯。

Paralellel.For也有System.IO._ConsoleStream.Write()（下方藍底列）但不是最吃重的部分，最吃重的部分在SyncTextWriter.WriteLine的JITutil_MonContention/AwareLock::Contention，由Contention（競爭、衝突）字眼可理解這部分是為調解多條Thread爭用WriteLine()衝突產生的額外邏輯。由此可證，在多執行緒環境密集呼叫Console.WriteLine()，必須付出相當代價，這項觀察是解釋「Parallel.For加上Console.WriteLine()後結果逆轉」的主要證據！

最後，CPU花了近1/3時間用在Synchronization（同步處理），我們也檢視一下For與Parallel.For的不同：

For的同步很單純，只有一SwapContext，花了869ms，等於整個執行階段的時間長度，應該是Process開始、結束引發的Thread切換。

Parallel.For花在同步的時間明顯多出許多，高達5秒以上（各Thread耗用時間的總和），其中SwapContext花了2.5秒，KeRemoveQueueEx也花了2.46秒，印證增加Thread數的Context Switch成本。

Context Switch成本及資源競爭副作用是多工作業的老議題，藉由Concurrency Visualizer，我們得以一窺多執行緒運作的奧祕，對相關議題也有了新的詮釋！所以呢，你知道的…

又到了呼口號時間：Concurrency Visualizer好強哦！Visual Studio好威呀！