聊一聊 dotnet-trace 調查 lock鎖競爭-有解無憂

一：背景

1. 講故事

最近在分析一個 linux 上的 dump，最后的誘因是大量的lock鎖誘發的高頻背景關系切換，雖然問題告一段落，但我還想知道一點資訊，所謂的高頻到底有多高頻？鎖競爭到底是一個怎樣的鎖競爭？如果了解這些資訊對我們后續分析此類問題非常有幫助，

要想獲取此類資訊，看 dump 肯定是沒有用的，只能給程式安裝一個攝像頭，在 Windows 平臺上可以在 perfview 上配一個 Microsoft-Windows-DotNETRuntime:ContentionKeyword 事件輕松搞定，截圖如下：

但 PerfView 是和 Windows 深度系結的，那在 Linux 上怎么辦呢？對，有朋友知道用 dotnet-trace，

二：探究 dotnet-trace

1. 如何監控 lock 競爭

dotnet-trace 是 CLR 團隊寫的一個跨平臺的小工具，專門用于獲取 .NET 程式的各種事件，可以理解成 PerfView 的一個子集，這里安裝就不說了，詳見官方檔案：https://learn.microsoft.com/en-us/dotnet/core/diagnostics/dotnet-trace

查閱檔案之后，只需要在 --clrevents 中配 contention 事件即可，詳情參見檔案：https://learn.microsoft.com/en-us/dotnet/fundamentals/diagnostics/runtime-contention-events

2. 測驗案例

為了方便解讀，這里我故意造一個 鎖護送 現象，參考代碼如下：


    internal class Program
    {
        public static object lockMe = new object();

        static void Main(string[] args)
        {
            long i = 10;

            Parallel.For(0, int.MaxValue, new ParallelOptions() { MaxDegreeOfParallelism = 4 }, (j) =>
            {
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
                lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
            });
        }
    }

將程式跑起來后，使用 dotnet-trace ps 找到 PID，再用 dotnet-trace 進行跟蹤，這里持續跟蹤 1分鐘，


[root@localhost ~]# dotnet-trace ps
 3316  dotnet  /usr/share/dotnet/dotnet  dotnet ConsoleApp3.dll  

[root@localhost ~]# dotnet-trace collect -p 3316 --clrevents contention --duration 00:00:01:00

Provider Name                           Keywords            Level               Enabled By
Microsoft-Windows-DotNETRuntime         0x0000000000004000  Informational(4)    --clrevents

Process        : /usr/share/dotnet/dotnet
Output File    : /root/dotnet_20230509_105906.nettrace
Trace Duration : 00:00:01:00
[00:00:01:00]	Recording trace 29.7885  (MB)
Press <Enter> or <Ctrl+C> to exit...148  (MB)
Stopping the trace. This may take several minutes depending on the application being traced.

Trace completed.

[root@localhost ~]# ls

anaconda-ks.cfg  dotnet_20230509_105906.nettrace  Music     Templates
Desktop          Downloads                        Pictures  Videos
Documents        initial-setup-ks.cfg             Public

3. nettrace 檔案分析

至于分析 dotnet_20230509_105906.nettrace 的工具就特別多了，dotnet-trace，perf，perfview，visualstudio，不過我個人建議還是使用 prefview，因為它的洞察能力會更好，用 perfview 打開之后點擊 EventStats 觀察統計資訊：

從圖中可以看到 1min 的時間內生成了總計將近 200w 的 start 和 stop 事件，

有了統計資訊還不行，我還想知道每一次 start 的詳細資訊，可以點擊 perfview 中的 Events 面板中的 Microsoft-Windows-DotNETRuntime/Contention/Start 事件，可以看到記錄中每一次爭搶的開始時間，

有些朋友可能要問了，Start 和 Stop 到底代表什么意思，簡而言之就是爭搶的開始時間和結束時間，時間差就是排隊時間，截圖如下：

從圖中可以看到，某些競爭鎖的時候耗費了 1ms 的時間，同時得到調度的執行緒也不是串行的，比如 4232 號執行緒就得到了兩次連續執行，

接下來回答最后一個問題，除了看到每一次lock競爭的詳細資訊，能不能看到每一次 lock 時的代碼呼叫堆疊呢？當然是可以的，畢竟 HasStack="True" ThreadID="3,316" ProcessorNumber="0" ContentionFlags="Managed" ClrInstanceID="0" 中的 HasStack="True" 就是告訴當前是有呼叫堆疊資訊的，在 Time MSec 列點擊右鍵選擇 Open Any Stacks，

從圖中的執行緒堆疊可以看到，Start 事件是由 Main 方法中的 Parallel.For 誘發的，非常清楚，

三：總結

dotnet-trace 是一個非常強大的跨平臺性能分析工具，構建在 EventPipe 之上，特點就是跨平臺，除了對鎖競爭外，還有其他的各種有趣的事件，有興趣的朋友可以查閱查閱，

轉載請註明出處，本文鏈接：https://www.uj5u.com/net/552068.html

標籤：.NET技术

上一篇：開源.NetCore通用工具庫Xmtool使用連載 - 散列演算法篇

下一篇：返回列表