使用dotnet-dump 查找 .net core 3.0 占用CPU 100%的原因 - 好文

　　公司的产品一直紧跟 .net core 3.0 preview 不断升级, 部署到 Linux 服务器后, 偶尔会出现某个进程CPU占用100%.
　　由于服务部署在云上, 不能使用远程调试; 在局域网内的Linux 服务器或 Windows开发机上又不能重现这个问题, 联想到Java的jstack,
很是羡慕啊. 想到.net core 已经出来这么久了, 还是试着找找看吧, 结果还真找到一篇博客Introducing diagnostics
improvements in .NET Core 3.0
<https://devblogs.microsoft.com/dotnet/introducing-diagnostics-improvements-in-net-core-3-0/>

　　这篇文章介绍了3个工具

* dotnet-counters: 实时统计runtime的状况, 包括 CPU、内存、GC、异常等
* dotnet-trace: 类似性能探测器
* dotnet-dump: 程序崩溃时使用该工具
　　这次使用的是dotnet-dump, 即使程序没有崩溃, 也可以dump程序快照, 用于分析

实验环境

ubuntu-16.04.5-desktop-amd64
SDK 3.0.100-preview6-012264

1. 新建一个简单Console程序(只能是 .net core 3.0的程序, 不支持 .net core 2.2), 模拟CPU占用100%的情况
mkdir NetCoreDumpTest && cd NetCoreDumpTest dotnet new console
编辑Program.cs
namespace NetCoreDumpTest { using System; using System.Threading.Tasks; class
Program {static void Main(string[] args) { Task.Factory.StartNew(() =>
PrintNumber("Print", 5)); Console.WriteLine("Press any key to exit.");
Console.ReadKey(); }static void PrintNumber(string message, int startNumber) {
var number = startNumber; while (true) Console.WriteLine($"{message} {number++}"
); } } }

2. 安装dotnet-dump
dotnet tool install --global dotnet-dump --version 1.0.4-preview6.19311.1
提示
If you are using bash, you can add it to your profile by running the following
command:cat << \EOF >> ~/.bash_profile # Add .NET Core SDK tools export PATH="
$PATH:/home/****/.dotnet/tools" EOF You can add it to the current session by
running the following command: export PATH="$PATH:/home/****/.dotnet/tools" You
can invoke the tool using the following command: dotnet-dump Tool 'dotnet-dump'
(version'1.0.4-preview6.19311.1') was successfully installed.
建议将 $HOME/.dotnet/tools加入到PATH, 好吧, 照着做吧, 记得使用下面的命令使设置立即生效
source ~/.bash_profile

3. 使用 dotnet NetCoreDumpTest.dll 启动我们的问题程序, 然后使用 ps -ef | grep dotnet
查看程序的进程ID, 可以看到进程ID是 3411
ps -ef | grep dotnet
z*****e 3411 1464 22 07:51 pts/8 00:00:59 dotnet NetCoreDumpTest.dll z*****e
3431 2935 0 07:55 pts/9 00:00:00 grep --color=auto dotnet
针对进程3411, 我们还需要知道是哪个线程占CPU, 使用 top -Hp 3411 可以列出所有线程, 由于top每隔3秒刷新一次,
所以可能需要多观察几秒才能看到具体是哪个线程占用CPU比较高, 这里我们可以看到是PID=3418的线程(Linux的进程ID和线程ID请自行了解一下).
top -Hp 3411 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3418 z*****e
20 0 2997700 29060 22400 R 10.3 1.4 0:20.68 dotnet 3411 z*****e 20 0 2997700
29060 22400 S 0.0 1.4 0:00.11 dotnet 3412 z*****e 20 0 2997700 29060 22400 S 0.0
1.4 0:00.02 dotnet 3413 z*****e 20 0 2997700 29060 22400 S 0.0 1.4 0:00.00
dotnet3414 z*****e 20 0 2997700 29060 22400 S 0.0 1.4 0:00.00 dotnet 3415
z*****e20 0 2997700 29060 22400 S 0.0 1.4 0:00.01 dotnet 3416 z*****e 20 0
2997700 29060 22400 S 0.0 1.4 0:00.00 dotnet 3417 z*****e 20 0 2997700 29060
22400 S 0.0 1.4 0:00.00 dotnet 3421 z*****e 20 0 2997700 29060 22400 S 0.0 1.4 0
:00.00 dotnet

获取dump, 只能正对进程进行dump, 所以我们输入的是 3411
dotnet-dump collect -p 3411 Writing minidump with heap to /tmp/
core_20190623_075649 Complete

4. 分析

dotnet-dump analyze core_20190623_075649

使用clrthreads 查看所有线程
>clrthreads ThreadCount: 4 UnstartedThread: 0 BackgroundThread: 3
PendingThread:0 DeadThread: 0 Hosted Runtime: no Lock DBG ID OSID ThreadOBJ
State GC Mode GC Alloc Context Domain Count Apt Exception0 1 d53
0000000001307D8020020 Preemptive 0000000000000000:0000000000000000
0000000001306450 1 Ukn 4 2 d57 000000000135BBD0 21220 Preemptive
0000000000000000:0000000000000000 0000000001306450 0 Ukn (Finalizer) 6 3 d59
00007F666C0009F01020220 Preemptive 0000000000000000:0000000000000000
0000000001306450 0 Ukn (Threadpool Worker) 7 4 d5a 000000000130DA40 1021220
Preemptive 00007F6678106860:00007F6678106F200000000001306450 1 Ukn (Threadpool
Worker)
我们关心的线程3418的16进制是d5a, 也就是最后一行, 它的DBG是7, 我们需要使用 setthread 7, 将其设置为当前操作的线程

然后使用 clrstack 获取线程调用信息
> setthread 7 > clrstack OS Thread Id: 0xd5a (7) Child SP IP Call Site
00007F6715561558 00007f671a2bd4bd [InlinedCallFrame: 00007f6715561558] Interop
+Sys.Write(System.Runtime.InteropServices.SafeHandle, Byte*, Int32)
00007F6715561558 00007f669f669a9e [InlinedCallFrame: 00007f6715561558] Interop
+Sys.Write(System.Runtime.InteropServices.SafeHandle, Byte*, Int32)
00007F6715561540 00007F669F669A9E ILStubClass.IL_STUB_PInvoke 00007F67155615E0
00007F669F67333E
System.ConsolePal.Write(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*,
Int32, Boolean) 00007F67155616A0 00007F669F67360C
System.ConsolePal.Write(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[],
Int32, Int32, Boolean) [/_/src/System.Console/src/System/ConsolePal.Unix.cs @
1236] 00007F67155616C0 00007F669F672B2A System.IO.StreamWriter.Flush(Boolean,
Boolean) [/_/src/System.Private.CoreLib/shared/System/IO/StreamWriter.cs @ 261]
00007F6715561710 00007F669F6729F3
System.IO.StreamWriter.WriteLine(System.String) [
/_/src/System.Private.CoreLib/shared/System/IO/StreamWriter.cs @474]
00007F6715561760 00007F669F6727D3 System.IO.TextWriter
+SyncTextWriter.WriteLine(System.String)
[/_/src/System.Private.CoreLib/shared/System/IO/TextWriter.cs @891]
00007F67155617A0 00007F669F672770 System.Console.WriteLine(System.String) [
/_/src/System.Console/src/System/Console.cs @550] 00007F67155617C0
00007F669F663791 NetCoreDumpTest.Program.PrintNumber(System.String, Int32) [
/home/zhouke/NetCoreDumpTest/Program.cs @18] 00007F6715561800 00007F669F6636D9
NetCoreDumpTest.Program+<>c.<Main>b__0_0() 00007F6715561820 00007F669F1872A1
System.Threading.Tasks.Task.InnerInvoke() [
/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @2466]
00007F6715561840 00007F669F18CBC2 System.Threading.Tasks.Task
+<>c.<.cctor>b__274_0(System.Object)
[/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @2445]
00007F6715561850 00007F669F171AF2
System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread,
System.Threading.ExecutionContext, System.Threading.ContextCallback,
System.Object) [
/_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @289]
00007F6715561890 00007F669F187111
System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task
ByRef, System.Threading.Thread) [
/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @2406]
00007F6715561910 00007F669F186F28
System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread) [
/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @2344]
00007F6715561930 00007F669F186EBB
System.Threading.Tasks.Task.ExecuteFromThreadPool(System.Threading.Thread)
00007F6715561940 00007F669F17B754
System.Threading.ThreadPoolWorkQueue.Dispatch() [
/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @663]
00007F67155619C0 00007F669F169A5B
System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() [
/_/src/System.Private.CoreLib/src/System/Threading/ThreadPool.CoreCLR.cs @29]
00007F6715561D50 00007f6718a1ccaf [DebuggerU2MCatchHandlerFrame:
00007f6715561d50]

哗啦啦一大片, 有点Java调用堆栈的味道, 不过我们还是找到了我们的问题代码

NetCoreDumpTest.Program.PrintNumber(System.String, Int32)

有时候我们想知道传入的什么参数导致CPU占用高, 可以给clrstack加上参数 -a
> clrstack -a .............. 00007F0DD6FFC7C0 00007F0D6EEF3791
NetCoreDumpTest.Program.PrintNumber(System.String, Int32) [
/home/zhouke/NetCoreDumpTest/Program.cs @18] PARAMETERS: message (
0x00007F0DD6FFC7E8) = 0x00007f0d4800b8b0 startNumber (0x00007F0DD6FFC7E4) =
0x0000000000000005 LOCALS: 0x00007F0DD6FFC7E0 = 0x000000000014e42b
0x00007F0DD6FFC7DC = 0x0000000000000001 ...............
可以看到PARAMETERS里, startNumber作为值类型, 可以直接看到数值为5, 而message是引用类型,
指向0x00007f0d4800b8b0, 这时候需要用到 dumpobj 命令
> dumpobj 0x00007f0d4800b8b0 Name: System.String MethodTable: 00007f0d6ef70f90
EEClass: 00007f0d6eede1c0 Size:32(0x20) bytes File:
/home/zhouke/dotnet/shared/Microsoft.NETCore.App/3.0.0-preview6-27804-01/
System.Private.CoreLib.dllString: Print Fields: MT Field Offset Type VT Attr
Value Name 00007f0d6ef6a138 400022b8 System.Int32 1 instance 5 _stringLength
00007f0d6ef66f38 400022c c System.Char1 instance 50 _firstChar 00007f0d6ef70f90
400022d108 System.String 0 static 00007f0d47fff360 Empty
好了, 可以看到它是一个字符串, 内容为 "Print"

假如message是一个复杂类型, 可以查看Fields下面的信息进一步查看

clrstack 还有一个实验性质的参数 -i, 协助查看各种变量信息, 需要用到lldb, 按照官方教程, 我暂时没有实验成功.

查看进程ID和线程ID, 更方便的方法是 htop(需要安装), 然后按 F4 进行过滤, 输入dotnet 即可

这张图是重新运行问题程序的结果, 进程ID和线程ID与前面不一样

第二行白色的是进程ID=1650, 第一行CPU占用高, 是问题线程ID=1658

End

热门工具换一换