一:背景
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
之上,特點就是跨平臺,除了對鎖競爭外,還有其他的各種有趣的事件,有興趣的朋友可以查閱查閱。