網友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好威呀!


Comments

# by Loops

暗黑大您好~ 用Console.Write本來只是想要觀看執行完成度,結果沒想到會因資源衝突造成速度拖慢,真是得不償失~ TAT" 看完超詳細的資源分析總算找到翻船的原因了! 看完您另一篇陰溝翻船文章分析,想到以前也曾比較過類似案例,當時的狀況是處理的工作不多(迴圈 i = 1~400),使用平行計算反而處理效能變差,追查原因發現,一開始分配工作(如文中所說放工作到Queue...等前置處理)的時候就用掉了不少時間。除非處理大量工作,否則得不償失。 Concurrency Visualizer的使用超威,觀察資源使用狀況來視覺化分析程式的執行效能正是我最近在找的工具,趕緊下載來玩玩看~~

Post a comment


66 + 1 =