前言

我在上一篇文章《記一次 .NET 程序的性能優(yōu)化實戰(zhàn)（1）—— 使用 process explorer 快速定位問題代碼》中用 process explorer 定位到了導致程序運行緩慢的原因——使用了 .NET 中的正則表達式。.NET 中的正則表達式真這么慢嗎？帶著疑問，開始了本次的探索之旅。喜歡刨根問底的小伙伴兒快來一起看看吧！

在開始之前，我還是把關(guān)鍵函數(shù)貼一下，大家也可以看看到底哪里寫的有問題。代碼如下：

private static bool IsSplitter(string curLine)
{
  var splitterRegex = new Regex(@"-{100,}", RegexOptions.Compiled | RegexOptions.IgnoreCase);
  MatchCollection matches = splitterRegex.Matches(curLine);
  return (matches.Count > 0);
}

選擇優(yōu)化工具

不知道都使用過哪些性能優(yōu)化工具呢？我主要專注于 windows 下的 c/c++/c# 開發(fā)，不涉及其它語言，也不涉及其它平臺。這里列舉幾個我用過的性能優(yōu)化工具。

• intel vtune

  intel 出品的性能優(yōu)化工具。優(yōu)點：功能強大，跨平臺，支持多種編程語言。缺點：占用空間太大，對硬件要求高，有一定的使用門檻，不免費。

• visual studio

  高版本的 vs 自帶性能分析工具（應該從 vs2013 就有了？），但是我很少用 vs 來分析性能問題。

• process monitor
  嗯，你沒看錯，process monitor 不僅可以用來排錯，也可以用來做性能分析，只不過不適合源碼級別的性能分析。我也很少用它來分析性能問題，主要用來排錯。

• .NET 相關(guān)的性能優(yōu)化工具。

  • JetBrains dotTrace

  • JetBrains dotMemory

    對這兩個工具不熟悉？沒關(guān)系，相信做 .NET 開發(fā)的小伙伴兒一定聽過或者用過大名鼎鼎的 ReShaper。這幾個工具是同一個公司出品的。BTW，這個公司還開發(fā)了一個非常好用的反編譯工具 dotPeek。

  • .NET Memory Profiler

• 基于 ETW (Event Trace for Windows) 的各種工具，適用于原生和托管程序。

  • perfmon

    windows 系統(tǒng)自帶的基于 ETW 的性能分析工具，真正的免安裝。

  • WPR/WPRUI/xperf

    微軟性能分析工具集（Windows Performance Toolkit）提供的 ETW 捕獲工具，可以使用 WPA 等性能分析工具進行查看。

  • WPA (Windows Performance Analyzer)

    微軟性能分析工具集提供性能分析工具，與 WPR 等抓取工具同時使用。圖形界面極其強大，但是學習曲線比較陡峭，不容易上手。

• UIforETW

  google 大佬 Bruce Dawson 基于 WPT 開發(fā)的 ETW 捕獲工具。開源免費。對 WPT 做了一層封裝，額外提供了的按鍵記錄功能。

  他的博客 Random ASCII 有大量高質(zhì)量的關(guān)于性能優(yōu)化的文章，強烈推薦閱讀。

• PerfView

  微軟開發(fā)的基于 ETW 的性能分析工具，集抓取和分析于一身的工具。開源免費，綠色免安裝，體積小，分析功能強大，雖然圖形界面相對薄弱，但是分組過濾功能非常強大。與 WPA 一樣不太容易上手，但是可以非常方便的獲取提示信息，而且有配套的視頻教程。尤其適合分析 .NET 程序的性能問題。

  說明：基于 ETW 機制的工具有一個弊端，一般情況下，ETW 是針對整個系統(tǒng)進行收集的，不太適合長時間采集，在采集之前一定要想好要收集哪些信息。

我電腦中必備的工具有 PerfView, WPT, UIforETW, vs, sysinternals。因為本次優(yōu)化的是 .NET 程序，所以首選 PerfView。

采集性能數(shù)據(jù)

運行 PerfView.exe，點擊 Collect 菜單，然后點擊 Collect 菜單項（會有提升權(quán)限的提示），在彈出的采集界面中保持默認設(shè)置，點擊 Start Collection 按鈕即可開始采集。采集開始后，執(zhí)行 ParseTfsLog.exe -b bug.csv，ParseTfsLog.exe 。程序執(zhí)行完畢后，在 PerfView 中點擊 Stop Collection 即可停止采集。

耐心等待一會，就可以在 PerfView 主界面的左側(cè)看到剛剛采集到的日志文件了。

初步分析

雙擊日志文件（PerfViewData.etl.zip），可以看到幾個視圖，如下圖所示：

perfview-show-relative-view

因為 ParseTfsLog 這個簡單的小程序只使用了單線程，在執(zhí)行過程中基本占滿了一個 CPU（運行在 8 核心的機器上，CPU 占用率大概是 12.5%）。

parse-tfs-log-tool-cpu-usage

根據(jù)以上信息，猜測這是一個 CPU 占用率過高的問題，優(yōu)先關(guān)注 CPU 使用率問題，雙擊 CPU Stacks 視圖進行查看。

說明： PerfView 中的 CPU Stacks 視圖相當于 WPA 中的 CPU Usage (Sample) 視圖。記錄的是 CPU 采樣數(shù)據(jù)，默認是 1 毫秒采樣一次（采樣頻率最快可以調(diào)整到 1/8 毫秒）。也就是一條數(shù)據(jù)基本上等于 1 毫秒。

在彈出的 Select Process Window 窗口中，列出了系統(tǒng)中所有的進程，可以看到 ParseTfsLog 排在第 1 位。

select-parse-tfs-log-tool-in-perfview-cpu-usage-view

雙擊 ParseTfsLog 所在的行，即可查看 ParseTfsLog 進程的事件，如下圖：

view-cpu-stacks-of-parse-tfs-log

在開始分析前，先簡單介紹一下上圖中涉及到的幾個關(guān)鍵點，對理解采集到的數(shù)據(jù)非常有幫助。

• Start 和 End 表示采集的起始時間和終止時間。如果只關(guān)心某一時間段內(nèi)的數(shù)據(jù)，可以調(diào)整起始時間和終止時間。這兩個值可以單獨修改其中的一個，也可以通過 Set Time Range (Alt+R) 修改。

• GroupPats 表示列表中顯示的記錄是按什么規(guī)則分組的，默認選擇的是 [Just My App] \debug\%!->;!=>OTHER。意思是 .exe 所在路徑以外的任何模塊的任何代碼都會被當成 OTHER。比如，第一條記錄被歸類到 OTHER 里了，因為這條記錄對應的地址是在 system.ni 模塊中的，該模塊并不在 ParseTfsLog.exe 所在的目錄下。圖中第 5 條記錄屬于 CommandLine.dll 模塊（與 .exe 在同一個目錄下），圖中最后 3 條記錄屬于 ParseTfsLog.exe 模塊。

• Fold% 表示折疊出現(xiàn)頻率低于指定值的記錄。設(shè)置一個合理的 Fold% 值，可以很好的過濾一些無關(guān)緊要的記錄。

• Exc % 和 Exc 表示當前函數(shù)的采樣百分比和采樣數(shù)，不包含子函數(shù)的采樣數(shù)據(jù)。

• Inc % 和 Inc 與 Exc 正好相反，表示包含當前函數(shù)及其子函數(shù)的采樣數(shù)據(jù)。

• When 表示事件發(fā)生的時刻，PerfView 會把整個時間段分成 32 份，然后把采樣數(shù)據(jù)按照時間點劃分到 32 份中的一份中。_ 表示沒有采樣數(shù)據(jù)。

• First 和 Last 分別表示第一條和最后一條采樣數(shù)據(jù)的時間點。

說明： 每一項都可以通過點擊右側(cè)的問號查看對應的幫助文檔。下圖是官方幫助文檔中的解釋。

perfview-official-help-document

簡單介紹后，就可以查看數(shù)據(jù)了。可以看到 MatchCollection.get_Count 占用了絕大部分 CPU（大概 89.7%）?？磥碚齽t表達式確實占用了很多時間。時間到底花在哪里了呢？點擊 MatchCollection.get_Count 對應的單元格，右鍵，選擇 Drill Into (Ctrl+D) 即可查看MatchCollection.get_Count() 函數(shù)內(nèi)部的詳細信息了。如下圖：

drill-into-matchCollection-get_Count

從上圖可知，clrjit!CILJit::compileMethod 居然占了大部分 CPU（Exc % 是 67.2，Inc % 是 98.6%）。

除了可以像上面那樣查看 MatchCollection.get_Count 的相關(guān)信息，還可以通過調(diào)用棧來自頂向下的查看相關(guān)信息。

查看調(diào)用棧

在查看前可以先取消分組（把 GroupPats 設(shè)置為 [no grouping] 即可取消分組，非必須，取消分組后可以看到更符合直覺的調(diào)用棧），然后選擇 CallTree 。逐層點擊調(diào)用棧進行查看，如下圖：

view-callstack

從上圖可知，采集到的數(shù)據(jù)跟實際代碼邏輯是完全吻合的。在 Parse() 函數(shù)中會不斷的調(diào)用 ReadOneLogData() 讀取提交記錄后，調(diào)用 ParseTfsLog.ParseOneLog() 對讀取到的記錄進行解析。ReadOneLogData() 和 ParseTfsLog.ParseOneLog() 內(nèi)部都會調(diào)用 IsSplitter() 判斷某一行是否是分隔符。

看來是 IsSplitter() 函數(shù)中的 JIT 相關(guān)代碼占用了大部分 CPU。

據(jù)我所知，一般一個托管函數(shù)只需要執(zhí)行一次 JIT，下次調(diào)用的時候會執(zhí)行編譯好的原生代碼。為什么會有這么多時間花在 JIT 上呢？在 JIT 哪些函數(shù)呢？

查看 JIT

在 PerfView 主界面，雙擊左側(cè)的 Events 視圖（在 CPU Stacks 下方），打開所有 ETW 事件記錄。可以根據(jù)各種條件進行過濾，也可以指定需要顯示的列。

• 在 Process Filter 對應的下拉框中輸入 ParseTfsLog （可以自動補全），表示只關(guān)心進程名字中含有 ParseTfsLog 的事件。
• 在 Filter 處輸入 jit 即可過濾 Event Types 中含有 jit 的 Event，這里只剩下了 Microsoft-Windows-DotNETRuntime/Method/JittingStarted，雙擊即可顯示該種 event 對應的所有記錄。
• 可以在 Text Filter 處輸入過濾關(guān)鍵字，只保留符合條件的記錄。! 表示反向過濾，比如 !CommandLine 表示不顯示包含 CommandLine 的記錄。
• 點擊 Columns To Display 右側(cè)的 Cols 按鈕設(shè)置需要顯示的列，按住 ctrl 或者 shift 選擇多列，選好后按回車即可。我選擇了三列：MethodNamespace，MethodName 和 *。列寬，列位置等均可手動調(diào)整，單擊列頭可以根據(jù)對應的列進行排序。

過濾后的事件如下圖所示：

view-filter-event

瀏覽過后發(fā)現(xiàn)，很多函數(shù)（包括 IsSplitter）都只被 JIT 了一次，符合認知。但是，有一種 JIT 比較特殊 —— MethodNamespace 為 dynamicClass 的 JIT 記錄。這種記錄對應的 MethodName 也比較有規(guī)律 —— 名稱+數(shù)字。比如，FindFirstChar9，Go9，Go20，Go21 等等。隨便選擇其中一條記錄，在其 Time MSec 列上右鍵，選擇 Open Any Stacks (Alt+s) 即可查看相關(guān)的調(diào)用棧。這里只列出 FindFirstChar9 對應的調(diào)用棧。如下圖：

view-callstack-of-jit-event

瀏覽了幾個函數(shù)后，感覺這些函數(shù)名好像是根據(jù)某些規(guī)則自動生成的。猜測是每次循環(huán)都會生成一次動態(tài)代碼。該如何確認這個猜想呢？

添加自定義 ETW 日志

在 IsSplitter() 函數(shù)內(nèi)部增加一個自動輸出 ETW 日志的功能，通過添加的 using 語句可以在進入函數(shù)和退出函數(shù)的時候分別輸出 ETW 日志（輸出日志的邏輯可以參考 AutoScopeLogger 類，這里從略）。修改后的 IsSplitter() 如下：

private static bool IsSplitter(string curLine)
{
  using (var autoLogger = new AutoScopeLogger("[IsSplitter]"))
  {
    var splitterRegex = new Regex(@"-{100,}", RegexOptions.Compiled | RegexOptions.IgnoreCase);
    MatchCollection matches = splitterRegex.Matches(curLine);
    return (matches.Count > 0);
  }
}

編譯通過后，重新使用 PerfView 采集 ETW 日志。這次需要設(shè)置 Additional Provider 為 *EtwLogger:*:*:@StacksEnabled=true 才能采集到新加的日志（@StacksEnabled=true 非必須，但是加上就可以看到調(diào)用棧）。這次 PerfView 的相關(guān)設(shè)置如下圖：

capture-with-additional-provider

采集好日志后再次查看 Events。這次 Event Types 的 Filters 需要改成 jit|Etwlogger，表示只關(guān)心 Event Types 中包含 jit 或者 EtwLogger 的 Event 。過濾后的記錄下圖所示：

view-filter-event-with-etwlogger

可以發(fā)現(xiàn)，基本每個 IsSplitter() 調(diào)用都會產(chǎn)生一個以 FindFirstChar 開始的動態(tài)函數(shù)，有時候也會產(chǎn)生以 Go 開頭的動態(tài)函數(shù)。

至此，基本上已經(jīng)知道程序運行慢的原因了 —— 每次調(diào)用 IsSplitter() 都會執(zhí)行 JIT。但是為什么呢？這就到了我的知識盲區(qū)了。只能搜搜看了，在 google 中輸入 .net regex slow，出來一堆結(jié)果，從里面發(fā)現(xiàn)了一個非常有幫助的官方文檔 —— Best practices for regular expressions in .NET。

官方文檔

Best practices 翻譯成中文就是最佳實踐，看名字就知道是好資料（不夸大，務實）。文檔里提到的一個比較重要的概念：

Defining a regular expression involves tightly coupling the regular expression engine with a regular expression pattern.

大白話翻譯就是：使用正則表達式前需要與正則表達式引擎綁定，綁定后就可以用來匹配文本了。

文檔里介紹了四種方法并分析了每種方法的適用場景，我按照理解整理如下：

文檔中關(guān)于 Compiled regular expressions 的說明摘錄如下：

Regular expression patterns that are bound to the regular expression engine through the specification of the Compiled option are compiled. This means that, when a regular expression object is instantiated, or when a static regular expression method is called and the regular expression cannot be found in the cache, the regular expression engine converts the regular expression to an intermediary set of operation codes, which it then converts to MSIL. When a method is called, the JIT compiler executes the MSIL.

當一個編譯型的正則表達式對象被實例化時，其對應的正則表達式在緩存中不存在的話，正則表達式引擎會把對應的正則表達式轉(zhuǎn)換成中間操作碼，然后被轉(zhuǎn)換成 MSIL。當對象的方法被調(diào)用時，JIT 會把對應的 MSIL 翻譯成機器指令。

這很好的解釋了前面通過 PerfView 采集到的大量 JIT 事件。

修改

知道問題出在哪，改起來就簡單了。IsSplitter() 中使用的正則表達式（固定不變，會被重復調(diào)用）完美符合使用靜態(tài)正則表達式的條件，所以可以把原來的邏輯使用 Regex.IsMatch() 重寫，重寫后的代碼如下：

private static bool IsSplitter(string curLine)
{
  using (var autoLogger = new AutoScopeLogger("[IsSplitter]"))
  {
    return Regex.IsMatch(curLine, @"-{100,}");
  }
}

另外一種改法是把函數(shù)內(nèi)部實例化的 Regex 對象改成全局變量，只實例化一次。在 IsSplitter() 中直接使用，修改后的代碼如下：

private static bool IsSplitter(string curLine)
{
  using (var autoLogger = new AutoScopeLogger("[IsSplitter]"))
  {
    // 修改 splitterRegex 為全局變量
    //var splitterRegex = new Regex(@"-{100,}", RegexOptions.Compiled | RegexOptions.IgnoreCase);
    MatchCollection matches = splitterRegex.Matches(curLine);
    return (matches.Count > 0);
  }
}

經(jīng)測試，不使用正則表達式（curLine.Contains()）需要 67ms，使用靜態(tài)正則表達式的版本需要 67ms，使用全局變量的版本需要 80ms。與未修改的版本（需要 11339ms）相比都有了極大的提高。而且靜態(tài)正則表達式版本的耗時與字符串查找耗時基本一致?？梢姡绻_使用正則表達式，效率還是非常高的。

compare-different-version

總結(jié)

• PerfView 絕對是 windows 平臺下的性能分析神器，開源免費，綠色免安裝，體積小巧，功能強大，既能采集又能分析。尤其適合分析 .NET 程序。
• 靜態(tài)正則表達式可以很好的使用正則表達式引擎的緩存，有效提升正則表達式的效率。
• 不要在循環(huán)中定義固定模式的編譯型正則表達式對象，使用靜態(tài)正則表達式替換。

參考資料

• PerfiView 幫助文檔
• Best practices for regular expressions in .NET

彩蛋

本來以為已經(jīng)調(diào)查完畢，而且優(yōu)化完成了，可以完美收工了。但是在測試過程中偶然去掉了實例化 Regex 的代碼中的 RegexOptions.Compiled，相關(guān)代碼如下:

private static bool IsSplitter(string curLine)
{
  using (var autoLogger = new AutoScopeLogger("[IsSplitter]"))
  {
    var splitterRegex = new Regex(@"-{100,}", RegexOptions.IgnoreCase);
    MatchCollection matches = splitterRegex.Matches(curLine);
    return (matches.Count > 0);
  }
}

您猜耗時多久？與全局變量版本非常接近，大概耗時 79ms。surprise!

run-without-compiled-option

看來還有東西沒“格”盡??！下篇文章再格吧。