聊一聊 dotnet-trace 调查 lock锁竞争 - 一线码农
source link: https://www.cnblogs.com/huangxincheng/p/17384543.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
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
之上,特点就是跨平台,除了对锁竞争外,还有其他的各种有趣的事件,有兴趣的朋友可以查阅查阅。
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK