ToB企服应用市场:ToB评测及商务社交产业平台

标题: TTD 专题 (第一篇)：C# 那些短命线程都在干什么？ [打印本页]
作者: 涛声依旧在    时间: 2022-10-6 09:16
标题: TTD 专题 (第一篇)：C# 那些短命线程都在干什么？
一：背景

1.讲故事

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

我们在 t2 时刻抓取的dump对查看 短命线程 毫无帮助，我根本就不知道这个线程生前执行了什么代码，为什么这么短命，还就因为这样的短命让 线程池 的线程暴增。
为了能尽最大努力解决此类问题，武器库中还得再充实一下，比如本系列要聊的 Time Travel Debug，即时间旅行调试。
二： Time Travel Debug

1. 什么是 时间旅行调试

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

1. 参考代码

这是我曾经遇到的一个真实案例，在没有 TTD 的协助下最终也艰难的找到了问题，但如果有 TTD 的协助简直就可以秒杀，为了方便说明，先上一个测试代码。
  1.     internal class Program
  2.     {
  3.         static void Main(string[] args)
  4.         {
  5.             for (int i = 0; i < 200; i++)
  6.             {
  7.                 Task.Run(() =>
  8.                 {
  9.                     Test();
  10.                 });
  11.             }
  13.             Console.ReadLine();
  14.         }
  15.         public static int index = 1;
  17.         static void Test()
  18.         {
  19.             Thread.Sleep(1000);
  21.             var i = 10;
  22.             var j = 20;
  24.             var sum = i + j;
  26.             Console.WriteLine($"i={index++},sum={sum}");
  27.         }
  28.     }
复制代码
程序跑完之后，我们抓一个dump文件，输出如下。
  1. 0:000> !t
  2. ThreadCount:      20
  3. UnstartedThread:  0
  4. BackgroundThread: 7
  5. PendingThread:    0
  6. DeadThread:       13
  7. Hosted Runtime:   no
  8.                                                                              Lock  
  9. DBG   ID     OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
  10.    0    1     12f8 00C4AF20  80030220 Preemptive  03C3FFAC:03C40000 00c462f8 -00001 Ukn
  11.    6    2     6a70 00C5BBD8     2b220 Preemptive  03C521B8:03C53FE8 00c462f8 -00001 MTA (Finalizer)
  12. XXXX    4        0 00C9FEB0   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  13.    7    5     6694 00CA0990   302b220 Preemptive  03C40314:03C41FE8 00c462f8 -00001 MTA (Threadpool Worker)
  14. XXXX    6        0 00CB53B8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  15. XXXX    7        0 00CB5958   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  16. XXXX    8        0 00CB4338   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  17. XXXX    9        0 00CB4C58   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  18. XXXX   10        0 08879278   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  19.    8   11     5d10 08879E90   102b220 Preemptive  03C2AC2C:03C2BFE8 00c462f8 -00001 MTA (Threadpool Worker)
  20. XXXX   12        0 0887D1F8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  21. XXXX   13        0 0887C0D8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  22. XXXX   14        0 0887AB70   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  23. XXXX   15        0 0887B400   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  24. XXXX   16        0 0887D640   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  25. XXXX   17        0 0887A728   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  26.    9   18     5658 0887C520   102b220 Preemptive  03C46684:03C47FE8 00c462f8 -00001 MTA (Threadpool Worker)
  27.   10   19      564 0887C968   102b220 Preemptive  03C4A664:03C4BFE8 00c462f8 -00001 MTA (Threadpool Worker)
  28. XXXX   20        0 0887AFB8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
  29.   11    3     547c 0887A2E0     2b220 Preemptive  03C50008:03C51FE8 00c462f8 -00001 MTA
复制代码
2. 为什么会有很多短命线程

从 windbg 的输出看有很多的 XXX，那原因是什么呢？ 还得先观察下代码，可以看到代码会给 ThreadPool 分发 100 次任务，每个任务也就 1s 的运行时间，这样的代码会造成 ThreadPool 的工作线程处理不及继而会产生更多的工作线程，在某一时刻那些 Sleep 后的线程又会规模性唤醒，ThreadPool 为了能够平衡工作者线程，就会灭掉很多的线程，造成 ThreadPool 中的暴涨暴跌现象。
因果关系是搞清楚了，但对于落地是没有任何帮助的，比如线程列表倒数第二行已死掉的线程：
  1. XXXX   20        0 0887AFB8   1039820 Preemptive  00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
复制代码
你是没法让它起死回生的，对吧？这时候就必须借助 TTD 录制一个小视频。
3. TTD 录制

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

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

稍等片刻，你会得到如下三个文件。
4. 分析思路

因为此时的 tid=20 的 OSID 已经不存在了，所以用 !tt 在时间刻度上折半查找 OSID 存在的 position。
  1. 0:007> !tt 94
  2. Setting position to 94% into the trace
  3. Setting position: 396DB:0
  4. (5ac8.20): Break instruction exception - code 80000003 (first/second chance not available)
  5. Time Travel Position: 396DB:0
  6. eax=00be602c ebx=00c7c2b0 ecx=00be6028 edx=0024e000 esi=00be6028 edi=00000000
  7. eip=77d8e925 esp=07acf1c8 ebp=07acf1c8 iopl=0         nv up ei pl nz na po nc
  8. cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
  9. ntdll!RtlEnterCriticalSection+0x15:
  10. 77d8e925 f00fba3000      lock btr dword ptr [eax],0   ds:002b:00be602c=ffffffff
  11. 0:007> !t
  12. ThreadCount:      20
  13. UnstartedThread:  0
  14. BackgroundThread: 19
  15. PendingThread:    0
  16. DeadThread:       0
  17. Hosted Runtime:   no
  18.                                                                          Lock  
  19. DBG   ID     OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
  20.   ...
  21.   24   20     145c 0887AFB8   302b220 Preemptive  03C4C1A4:03C4DFE8 00c462f8 -00001 MTA (Threadpool Worker)
复制代码
可以清楚的看到原来是 OSID =145c 及WindbgID=24 有了这个信息不代表此时它正在执行托管方法，所以我们还需要找到这个 145c 是何时出生的？
可以在 Events 输出信息中检索 id=0x145c 的线程出生信息。
  1. 0:024> dx -r2 @$curprocess.TTD.Events.Where(t => t.Type == "ThreadCreated").Select(t => t.Thread).Where(t=>t.Id==0x145c).Select(t=>t)
  2. @$curprocess.TTD.Events.Where(t => t.Type == "ThreadCreated").Select(t => t.Thread).Where(t=>t.Id==0x145c).Select(t=>t)               
  3.     [0x0]            : UID: 27, TID: 0x145C
  4.         UniqueId         : 0x1b
  5.         Id               : 0x145c
  6.         Lifetime         : [38B21:0, 3BB45:0]
  7.         ActiveTime       : [38B6A:0, 3BB45:0]
  8.         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 号线程的托管部分。
  1. 0:024> !tt 94
  2. Setting position to 94% into the trace
  3. Setting position: 396DB:0
  4. (5ac8.20): Break instruction exception - code 80000003 (first/second chance not available)
  5. Time Travel Position: 396DB:0
  6. eax=00be602c ebx=00c7c2b0 ecx=00be6028 edx=0024e000 esi=00be6028 edi=00000000
  7. eip=77d8e925 esp=07acf1c8 ebp=07acf1c8 iopl=0         nv up ei pl nz na po nc
  8. cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
  9. ntdll!RtlEnterCriticalSection+0x15:
  10. 77d8e925 f00fba3000      lock btr dword ptr [eax],0   ds:002b:00be602c=ffffffff
  11. 0:007> ~24s
  12. eax=00000000 ebx=0b1bfab8 ecx=00000000 edx=00000000 esi=00000001 edi=0b1bfab8
  13. eip=77dc196c esp=0b1bfa78 ebp=0b1bfadc iopl=0         nv up ei pl nz na pe nc
  14. cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000206
  15. ntdll!NtDelayExecution+0xc:
  16. 77dc196c c20800          ret     8
  17. 0:024> !clrstack
  18. OS Thread Id: 0x145c (24)
  19. Child SP       IP Call Site
  20. 0B1BFB50 77dc196c [HelperMethodFrame: 0b1bfb50] System.Threading.Thread.SleepInternal(Int32)
  21. 0B1BFBBC 07b90694
  22. 0B1BFBD0 03b99078 ConsoleApp1.Program.Test()
  23. 0B1BFC04 03b98a03 ConsoleApp1.Program+c.b__0_0()
  24. 0B1BFC10 07b9065d System.Threading.Tasks.Task.InnerInvoke() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2387]
  25. 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]
  26. 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]
  27. 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]
  28. 0B1BFCB8 03b9ff34 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2277]
  29. 0B1BFCC8 070f7a36 System.Threading.ThreadPoolWorkQueue.Dispatch()
  30. 0B1BFD24 070ff222 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs @ 63]
  31. 0B1BFDB0 070e6545 System.Threading.Thread.StartCallback() [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 105]
  32. 0B1BFF04 0307b9cf [DebuggerU2MCatchHandlerFrame: 0b1bff04]
复制代码
C# 的一个特性就是很多方法都是由 JIT 动态编译的，因为很多方法都是未编译，所以遇到编译事件的时候执行流很大概率就在托管层。
  1. 0:024> bp clrjit!CILJit::compileMethod
  2. 0:024> g
  3. Breakpoint 0 hit
  4. Time Travel Position: 3939B:12E9
  5. eax=07acf8c8 ebx=07acf9d4 ecx=503d34b0 edx=00000000 esi=502bca30 edi=503d34b0
  6. eip=502bca30 esp=07acf784 ebp=07acf9c8 iopl=0         nv up ei ng nz na po nc
  7. cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000282
  8. clrjit!CILJit::compileMethod:
  9. 502bca30 55              push    ebp
复制代码
免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！



欢迎光临 ToB企服应用市场:ToB评测及商务社交产业平台 (https://dis.qidao123.com/) Powered by Discuz! X3.4