PerfView专题 (第十四篇)： 洞察那些 C# 代码中的短命线程
一：背景
1. 讲故事
这篇文章源自于分析一些疑难dump的思考而产生的灵感，在dump分析中经常要寻找的一个答案就是如何找到死亡线程的生前都做了一些什么？参考如下输出：
0:001> !t
ThreadCount: 22
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 20
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 3a74 00efb368 2a020 Preemptive 02F2AF48:00000000 00ec2fa0 1 MTA
5 2 6758 00f07a48 2b220 Preemptive 00000000:00000000 00ec2fa0 0 MTA (Finalizer)
XXXX 3 0 00f31df0 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 4 0 00f34080 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 5 0 00f363a8 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 6 0 00f372e8 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 7 0 00f39f80 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 8 0 00f3cbd0 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 9 0 00f3d128 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 10 0 00f40630 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 11 0 00f43310 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 12 0 00f42db8 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 13 0 00f49180 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 14 0 00f4a228 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 15 0 00f53a28 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 16 0 00f56598 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 17 0 00f59180 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 18 0 00f59b28 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 19 0 00f5e8a0 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 20 0 00f5f248 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 21 0 00f63fc0 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
XXXX 22 0 00f66b50 1039820 Preemptive 00000000:00000000 00ec2fa0 0 Ukn (Threadpool Worker)
前面的 XXXX 代表线程已死亡，那谁能告诉我 ID=22 的线程生前执行了什么代码呢？其实去年我写了一篇如何用 WinDbg 去寻找程序中的短命线程。 TTD 专题 (第一篇)：C# 那些短命线程都在干什么？
虽然可以用 WinDbg 的 TTD 来解决，但也有很多的限制，诸如：
- 生产环境不能安装 windbg 或者 安装不上
- 不能对生产程序进行附加
所以这两点也制约了 TTD 的强大威力，那有没有轻量级以及无侵入的方式洞察呢？最近在看 perfview 的文档，发现完全可以使用内核中Thread 的 ETW相关事件来搞定。
二：Thread 的ETW事件
1. 使用 Thread 的短命线程
如果死亡线程背后没有标记 Threadpool Worker 的话，那就说明是代码自己用 new Thread 创建出来的线程，这种比较简单，观察 Windows Kernel/Thread/Start 或者 Microsoft-Windows-DotNETRunning/Thread/Creating 的ETW事件即可。
接下来写一段简单的案例代码：
internal class Program
{
static void Main(string[] args)
{
for (int i = 0; i < 5000; i++)
{
Test1();
}
Console.ReadLine();
}
public static int index = 1;
public static void Test1()
{
new Thread(() => { Test2(); }).Start();
}
public static void Test2()
{
Thread.Sleep(10);
var i = 10;
var j = 20;
var sum = i + j;
Console.WriteLine($"i={index++},sum={sum}");
}
}
代码非常简单，用 new Thread 创建了一个短命线程，接下来打开 Perfview 使用默认配置，完整的 Command 命令如下：
PerfView.exe "/DataFile:PerfViewData.etl" /BufferSizeMB:256 /StackCompression /CircularMB:500 /ClrEvents:GC,Binder,Security,AppDomainResourceManagement,Contention,Exception,Threading,JITSymbols,Type,GCHeapSurvivalAndMovement,GCHeapAndTypeNames,Stack,ThreadTransfer,Codesymbols,Compilation /NoGui /NoNGenRundown /Merge:True /Zip:True collect
程序跑完后可以用 WinDbg 的 !t 去看看凌乱现场，可以发现有大量的 XXX 线程。
0:008> !t
ThreadCount: 1386
UnstartedThread: 0
BackgroundThread: 2
PendingThread: 0
DeadThread: 1383
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 4114 02CAC9C8 2a020 Preemptive 0559F108:0559FFEC 02c9c488 -00001 MTA
6 2 31b4 02CBA5F0 2b220 Preemptive 00000000:00000000 02c9c488 -00001 MTA (Finalizer)
XXXX 3 0 02CCEC48 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 694 0 116C5B18 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 695 0 116C0578 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 696 0 116C1250 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 697 0 116BF8A0 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 698 0 116C5F60 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 699 0 116C38D8 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 700 0 116C74C8 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
...
XXXX 1380 0 115097C0 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 1381 0 115079C8 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 1382 0 1150B170 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 1383 0 1150AD28 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 1384 0 11508258 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
XXXX 1385 0 11505BD0 39820 Preemptive 00000000:00000000 02c9c488 -00001 Ukn
7 1386 6114 1150CF68 20220 Preemptive 055A07A8:055A1FEC 02c9c488 -00001 Ukn
收集一会之后停止收集，选中Thread的内核事件 Thread/Start，截图如下：
从卦中可以看到有大量的 Start 事件，我们挑选其中一个观察下线程栈，右键 Open Any Stacks 看看到底是什么代码发出了这个 ETW 事件，截图如下：
从卦中可以清晰的看到，原来是 Main() -> Test1() 方法创建的哈，终于水落石出。
2. 使用 ThreadPool 的短命线程
在真实场景中也有很多代码是用 ThreadPool 创建出来的短命线程，这种短命线程其实有一个特点，那就是曾经有大量的任务进队列，导致 ThreadPool 被迫生成很多的线程来应付，当任务全部被消灭后，ThreadPool 就会把那些被迫生成的线程全部给裁掉。
卸磨杀驴，真的好像我们的职场/(ㄒoㄒ)/~~。
所以突破点就是统计下 ThreadPoolEnqueueWork 事件，有了思路之后修改下测试代码。
public static void Test1()
{
Task.Run(() => { Test2(); });
}
这里有一个注意点，程序跑完之后还要稍等一两分钟，就是让ThreadPool把多余的Thread给灭掉，用 windbg 观察到的效果图就是 讲故事 那一节的，停止 perfview 收集后,寻找 ThreadPoolEnqueueWork 事件，截图如下：
从卦中可以看到有大量的 ThreadPoolEnqueueWork 事件，接下来可以选择右键菜单 Save View as Excel 导出到 Excel 中，然后对 Time Msec 进行分组排序，看下哪一个时间段有大量的任务进队列，指标高的时间段自然就是重点怀疑的。
这里要说一点 Time MSec 是 Trace Start Time 基础上的毫秒级偏移值。
举个例子: 4377.032 (4.37s) + 15:56:25.566 = 15:56:29.866
有了这些概念之后，找到问题区域的进队任务，观察下调用栈，大概率也能找到问题，从调用栈来看，原来是 Test1() 所致哈。。。 截图如下：
三：总结
相比WinDbg TTD的重模式，Perfiew真的很轻，而且无侵入性，这两个工具真的是珠联璧合，相得益彰。
