聊一聊用 Dotnet-Trace 調(diào)查 Lock鎖競(jìng)爭(zhēng)
一：背景
1. 講故事
最近在分析一個(gè) linux 上的 dump，最后的誘因是大量的lock鎖誘發(fā)的高頻上下文切換，雖然問(wèn)題告一段落，但我還想知道一點(diǎn)信息，所謂的高頻到底有多高頻？鎖競(jìng)爭(zhēng)到底是一個(gè)怎樣的鎖競(jìng)爭(zhēng)？如果了解這些信息對(duì)我們后續(xù)分析此類(lèi)問(wèn)題非常有幫助。
要想獲取此類(lèi)信息，看 dump 肯定是沒(méi)有用的，只能給程序安裝一個(gè)攝像頭，在 Windows 平臺(tái)上可以在 perfview 上配一個(gè) Microsoft-Windows-DotNETRuntime:ContentionKeyword 事件輕松搞定，截圖如下：
但 PerfView 是和 Windows 深度綁定的，那在 Linux 上怎么辦呢？對(duì)，有朋友知道用 dotnet-trace。
二：探究 dotnet-trace
1. 如何監(jiān)控 lock 競(jìng)爭(zhēng)
dotnet-trace 是 CLR 團(tuán)隊(duì)寫(xiě)的一個(gè)跨平臺(tái)的小工具，專(zhuān)門(mén)用于獲取 .NET 程序的各種事件，可以理解成 PerfView 的一個(gè)子集，這里安裝就不說(shuō)了，詳見(jiàn)官方文檔：https://learn.microsoft.com/en-us/dotnet/core/diagnostics/dotnet-trace
查閱文檔之后，只需要在 --clrevents 中配 contention 事件即可，詳情參見(jiàn)文檔：https://learn.microsoft.com/en-us/dotnet/fundamentals/diagnostics/runtime-contention-events
2. 測(cè)試案例
為了方便解讀，這里我故意造一個(gè) 鎖護(hù)送 現(xiàn)象，參考代碼如下：
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++;
});
}
}將程序跑起來(lái)后，使用 dotnet-trace ps 找到 PID，再用 dotnet-trace 進(jìn)行跟蹤，這里持續(xù)跟蹤 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 Public3. nettrace 文件分析
至于分析 dotnet_20230509_105906.nettrace 的工具就特別多了，dotnet-trace，perf，perfview，visualstudio，不過(guò)我個(gè)人建議還是使用 prefview，因?yàn)樗亩床炷芰?huì)更好，用 perfview 打開(kāi)之后點(diǎn)擊 EventStats 觀察統(tǒng)計(jì)信息：
從圖中可以看到 1min 的時(shí)間內(nèi)生成了總計(jì)將近 200w 的 start 和 stop 事件。
有了統(tǒng)計(jì)信息還不行，我還想知道每一次 start 的詳細(xì)信息，可以點(diǎn)擊 perfview 中的 Events 面板中的 Microsoft-Windows-DotNETRuntime/Contention/Start 事件，可以看到記錄中每一次爭(zhēng)搶的開(kāi)始時(shí)間。
有些朋友可能要問(wèn)了，Start 和 Stop 到底代表什么意思，簡(jiǎn)而言之就是爭(zhēng)搶的開(kāi)始時(shí)間和結(jié)束時(shí)間，時(shí)間差就是排隊(duì)時(shí)間，截圖如下：
從圖中可以看到，某些競(jìng)爭(zhēng)鎖的時(shí)候耗費(fèi)了 1ms 的時(shí)間，同時(shí)得到調(diào)度的線(xiàn)程也不是串行的，比如 4232 號(hào)線(xiàn)程就得到了兩次連續(xù)執(zhí)行。
接下來(lái)回答最后一個(gè)問(wèn)題，除了看到每一次lock競(jìng)爭(zhēng)的詳細(xì)信息，能不能看到每一次 lock 時(shí)的代碼調(diào)用棧呢？當(dāng)然是可以的，畢竟 HasStack="True" ThreadID="3,316" ProcessorNumber="0" Cnotallow="Managed" ClrInstanceID="0" 中的 HasStack="True" 就是告訴當(dāng)前是有調(diào)用棧信息的，在 Time MSec 列點(diǎn)擊右鍵選擇 Open Any Stacks。
從圖中的線(xiàn)程?？梢钥吹剑琒tart 事件是由 Main 方法中的 Parallel.For 誘發(fā)的，非常清楚。
三：總結(jié)
dotnet-trace 是一個(gè)非常強(qiáng)大的跨平臺(tái)性能分析工具，構(gòu)建在 EventPipe 之上，特點(diǎn)就是跨平臺(tái)，除了對(duì)鎖競(jìng)爭(zhēng)外，還有其他的各種有趣的事件，有興趣的朋友可以查閱查閱。
