PerfView专题 (第十四篇)：洞察那些 C# 代码中的短命线程

perfview,专题,第十,四篇,洞察,那些,c#,代码,短命,线程 · 浏览次数 : 400

小编点评

**卦中主要有以下内容：** * ThreadPool 相关事件： ThreadPoolEnqueueWork、ThreadPoolComplete、ThreadPoolShutdown * Main线程相关事件： Main()、Test1() * ThreadPool 创建的短命线程相关事件： Task、Run、Task.Run * ThreadPool 和 Windows Event Performance (WEP) 的关系： WEP是 Windows 事件的性能指标，WEP可以记录 ThreadPool 的EnqueueWork、Complete、Shutdown 事件 **重点分析：** * ThreadPoolEnqueueWork 事件：表示线程进队列，该线程会根据该事件执行完成。 * ThreadPoolComplete 事件：表示线程完成执行，该线程会根据该事件执行完成。 * ThreadPoolShutdown 事件：表示线程退出，该线程会被回收。 * ThreadPoolCreate 事件：表示创建新的线程，该线程会根据该事件执行完成。 * ThreadPool 和 WEP 的关系： WEP可以记录 ThreadPool 的EnqueueWork、Complete、Shutdown 事件，这些事件可以用于分析 ThreadPool 的性能。 **主要问题：** * 如何统计 ThreadPoolEnqueueWork 事件？ * 如何找到调用 ThreadPool 的线程？ * 如何分析 ThreadPool 的性能？ **解决方案：** * 使用 Windbg 观察 WEP，分析 ThreadPool 的EnqueueWork、Complete、Shutdown 事件。 * 使用 ThreadPool 创建的短命线程，观察线程状态。 * 使用 ThreadPool 和 WEP 的关系，分析 ThreadPool 的性能。

正文

一：背景

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真的很轻，而且无侵入性，这两个工具真的是珠联璧合，相得益彰。