TTD 专题 (第一篇)：C# 那些短命线程都在干什么？

乎语百科 2022-10-06 11:10:16 409 0

一：背景

1.讲故事

在分析的众多dump中，经常会遇到各种奇葩的问题，仅通过dump这种快照形式还是有很多问题搞不定，而通过 perfview 这种粒度又太粗，很难找到问题之所在，真的很头疼，比如本篇的 短命线程 问题，参考图如下：

我们在 t2 时刻抓取的dump对查看 短命线程 毫无帮助，我根本就不知道这个线程生前执行了什么代码，为什么这么短命，还就因为这样的短命让线程池的线程暴增。

为了能尽最大努力解决此类问题，武器库中还得再充实一下，比如本系列要聊的 Time Travel Debug，即时间旅行调试。

二： Time Travel Debug

1. 什么是时间旅行调试

如果说 dump 是程序的一张照片，那 TTD 就是程序的一个短视频，很显然短视频的信息量远大于一张照片，因为视频记录着疑难杂症的前因后果，参考价值巨大，简直就是银弹般的存在。

三：案例演示

1. 参考代码

这是我曾经遇到的一个真实案例，在没有 TTD 的协助下最终也艰难的找到了问题，但如果有 TTD 的协助简直就可以秒杀，为了方便说明，先上一个测试代码。


    internal class Program
    {
        static void Main(string[] args)
        {
            for (int i = 0; i < 200; i++)
            {
                Task.Run(() =>
                {
                    Test();
                });
            }

            Console.ReadLine();
        }
        public static int index = 1;

        static void Test()
        {
            Thread.Sleep(1000);

            var i = 10;
            var j = 20;

            var sum = i + j;

            Console.WriteLine($"i={index++},sum={sum}");
        }
    }

程序跑完之后，我们抓一个dump文件，输出如下。


0:000> !t
ThreadCount:      20
UnstartedThread:  0
BackgroundThread: 7
PendingThread:    0
DeadThread:       13
Hosted Runtime:   no
                                                                             Lock
 DBG   ID     OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1     12f8 00C4AF20  80030220 Preemptive  03C3FFAC:03C40000 00c462f8 -00001 Ukn
   6    2     6a70 00C5BBD8     2b220 Preemptive  03C521B8:03C53FE8 00c462f8 -00001 MTA (Finalizer)
XXXX    4        0 00C9FEB0   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
   7    5     6694 00CA0990   302b220 Preemptive  03C40314:03C41FE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX    6        0 00CB53B8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX    7        0 00CB5958   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX    8        0 00CB4338   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX    9        0 00CB4C58   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX   10        0 08879278   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
   8   11     5d10 08879E90   102b220 Preemptive  03C2AC2C:03C2BFE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX   12        0 0887D1F8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX   13        0 0887C0D8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX   14        0 0887AB70   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX   15        0 0887B400   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX   16        0 0887D640   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX   17        0 0887A728   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
   9   18     5658 0887C520   102b220 Preemptive  03C46684:03C47FE8 00c462f8 -00001 MTA (Threadpool Worker)
  10   19      564 0887C968   102b220 Preemptive  03C4A664:03C4BFE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX   20        0 0887AFB8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  11    3     547c 0887A2E0     2b220 Preemptive  03C50008:03C51FE8 00c462f8 -00001 MTA

2. 为什么会有很多短命线程

从 windbg 的输出看有很多的 XXX，那原因是什么呢？还得先观察下代码，可以看到代码会给 ThreadPool 分发 100 次任务，每个任务也就 1s 的运行时间，这样的代码会造成 ThreadPool 的工作线程处理不及继而会产生更多的工作线程，在某一时刻那些 Sleep 后的线程又会规模性唤醒，ThreadPool 为了能够平衡工作者线程，就会灭掉很多的线程，造成 ThreadPool 中的暴涨暴跌现象。

因果关系是搞清楚了，但对于落地是没有任何帮助的，比如线程列表倒数第二行已死掉的线程：


XXXX   20        0 0887AFB8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)

你是没法让它起死回生的，对吧？这时候就必须借助 TTD 录制一个小视频。

3. TTD 录制

录制非常简单，选择 Lauch executable (advanced) 项再勾选 Record 即可，截图如下：

等程序执行完了或者你觉得时机合适再点击 Stop and Debug 停止录制，截图如下：

稍等片刻，你会得到如下三个文件。

ConsoleApp101.run 录制文件
ConsoleApp101.idx 录制的索引文件
ConsoleApp101.out 日志文件

4. 分析思路

找到 tid=20 的 OSID 线程ID

因为此时的 tid=20 的 OSID 已经不存在了，所以用 !tt 在时间刻度上折半查找 OSID 存在的 position。


0:007> !tt 94
Setting position to 94% into the trace
Setting position: 396DB:0
(5ac8.20): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 396DB:0
eax=00be602c ebx=00c7c2b0 ecx=00be6028 edx=0024e000 esi=00be6028 edi=00000000
eip=77d8e925 esp=07acf1c8 ebp=07acf1c8 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
ntdll!RtlEnterCriticalSection+0x15:
77d8e925 f00fba3000      lock btr dword ptr [eax],0   ds:002b:00be602c=ffffffff
0:007> !t
ThreadCount:      20
UnstartedThread:  0
BackgroundThread: 19
PendingThread:    0
DeadThread:       0
Hosted Runtime:   no
                                                                         Lock
 DBG   ID     OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
  ...
  24   20     145c 0887AFB8   302b220 Preemptive  03C4C1A4:03C4DFE8 00c462f8 -00001 MTA (Threadpool Worker)

可以清楚的看到原来是 OSID =145c 及WindbgID=24 有了这个信息不代表此时它正在执行托管方法，所以我们还需要找到这个 145c 是何时出生的？

找到当前视频中所有的 ThreadCreated 事件。

可以在 Events 输出信息中检索 id=0x145c 的线程出生信息。


0:024> dx -r2 @$curprocess.TTD.Events.Where(t => t.Type == "ThreadCreated").Select(t => t.Thread).Where(t=>t.Id==0x145c).Select(t=>t)
@$curprocess.TTD.Events.Where(t => t.Type == "ThreadCreated").Select(t => t.Thread).Where(t=>t.Id==0x145c).Select(t=>t)
    [0x0]            : UID: 27, TID: 0x145C
        UniqueId         : 0x1b
        Id               : 0x145c
        Lifetime         : [38B21:0, 3BB45:0]
        ActiveTime       : [38B6A:0, 3BB45:0]
        GatherMemoryUse  [Gather inputs, outputs and memory used by a range of execution within a thread]

从输出中可以看到, Lifetime 表示这个线程的一生, ActiveTime 则是从线程的Start处开始的，画个图如下：

接下来将进度条调到 !tt 38B21:0 处，那如何看代码进入到托管方法中呢？这个就得各显神通，我知道的有这么几种。

使用单步调试

先用 !tt 调整大致范围，然后用 p,pc,pt,t,tc,tt 微调，比如我们这篇的 !tt 94 就能获取到 tid=20 号线程的托管部分。


0:024> !tt 94
Setting position to 94% into the trace
Setting position: 396DB:0
(5ac8.20): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 396DB:0
eax=00be602c ebx=00c7c2b0 ecx=00be6028 edx=0024e000 esi=00be6028 edi=00000000
eip=77d8e925 esp=07acf1c8 ebp=07acf1c8 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
ntdll!RtlEnterCriticalSection+0x15:
77d8e925 f00fba3000      lock btr dword ptr [eax],0   ds:002b:00be602c=ffffffff
0:007> ~24s
eax=00000000 ebx=0b1bfab8 ecx=00000000 edx=00000000 esi=00000001 edi=0b1bfab8
eip=77dc196c esp=0b1bfa78 ebp=0b1bfadc iopl=0         nv up ei pl nz na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000206
ntdll!NtDelayExecution+0xc:
77dc196c c20800          ret     8
0:024> !clrstack
OS Thread Id: 0x145c (24)
Child SP       IP Call Site
0B1BFB50 77dc196c [HelperMethodFrame: 0b1bfb50] System.Threading.Thread.SleepInternal(Int32)
0B1BFBBC 07b90694
0B1BFBD0 03b99078 ConsoleApp1.Program.Test()
0B1BFC04 03b98a03 ConsoleApp1.Program+c.b__0_0()
0B1BFC10 07b9065d System.Threading.Tasks.Task.InnerInvoke() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2387]
0B1BFC1C 07b900cd System.Threading.Tasks.Task+c.<.cctor>b__272_0(System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2375]
0B1BFC24 07b90047 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs @ 268]
0B1BFC54 07b907d2 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2337]
0B1BFCB8 03b9ff34 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2277]
0B1BFCC8 070f7a36 System.Threading.ThreadPoolWorkQueue.Dispatch()
0B1BFD24 070ff222 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs @ 63]
0B1BFDB0 070e6545 System.Threading.Thread.StartCallback() [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 105]
0B1BFF04 0307b9cf [DebuggerU2MCatchHandlerFrame: 0b1bff04]

对 compileMethod 方法下断点

C# 的一个特性就是很多方法都是由 JIT 动态编译的，因为很多方法都是未编译，所以遇到编译事件的时候执行流很大概率就在托管层。


0:024> bp clrjit!CILJit::compileMethod
0:024> g
Breakpoint 0 hit
Time Travel Position: 3939B:12E9
eax=07acf8c8 ebx=07acf9d4 ecx=503d34b0 edx=00000000 esi=502bca30 edi=503d34b0
eip=502bca30 esp=07acf784 ebp=07acf9c8 iopl=0         nv up ei ng nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000282
clrjit!CILJit::compileMethod:
502bca30 55              push    ebp

标签： # c#