聊一聊 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. 测试案例

为了方便解读，这里我故意造一个 锁护送 现象，参考代码如下：

1.     internal class Program
2.     {
3.         public static object lockMe = new object();
5.         static void Main(string[] args)
6.         {
7.             long i = 10;
9.             Parallel.For(0, int.MaxValue, new ParallelOptions() { MaxDegreeOfParallelism = 4 }, (j) =>
10.             {
11.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
12.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
13.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
14.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
15.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
16.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
17.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
18.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
19.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
20.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
21.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
22.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
23.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
24.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
25.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
26.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
27.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
28.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
29.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
30.                 lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++; lock (lockMe) i++;
31.             });
32.         }
33.     }

复制代码

将程序跑起来后，使用  dotnet-trace ps 找到 PID，再用 dotnet-trace 进行跟踪，这里持续跟踪 1分钟。

1. [root@localhost ~]# dotnet-trace ps
2. 3316  dotnet  /usr/share/dotnet/dotnet  dotnet ConsoleApp3.dll  
4. [root@localhost ~]# dotnet-trace collect -p 3316 --clrevents contention --duration 00:00:01:00
6. Provider Name                           Keywords            Level               Enabled By
7. Microsoft-Windows-DotNETRuntime         0x0000000000004000  Informational(4)    --clrevents
9. Process        : /usr/share/dotnet/dotnet
10. Output File    : /root/dotnet_20230509_105906.nettrace
11. Trace Duration : 00:00:01:00
12. [00:00:01:00]        Recording trace 29.7885  (MB)
13. Press <Enter> or <Ctrl+C> to exit...148  (MB)
14. Stopping the trace. This may take several minutes depending on the application being traced.
16. Trace completed.
18. [root@localhost ~]# ls
20. anaconda-ks.cfg  dotnet_20230509_105906.nettrace  Music     Templates
21. Desktop          Downloads                        Pictures  Videos
22. 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.cnblogs.com/huangxincheng/archive/2023/05/09/17384543.html
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！