TTD 专题 (第一篇)：C# 那些短命线程都在干什么？
<h2 id="一背景">一：背景</h2><h3 id="1讲故事">1.讲故事</h3>
<p>在分析的众多dump中，经常会遇到各种奇葩的问题，仅通过dump这种快照形式还是有很多问题搞不定，而通过 perfview 这种粒度又太粗，很难找到问题之所在，真的很头疼，比如本篇的 <code>短命线程</code> 问题，参考图如下：</p>
<p><img src="https://img2022.cnblogs.com/blog/214741/202210/214741-20221006080823232-1948655554.png"></p>
<p>我们在 t2 时刻抓取的dump对查看 <code>短命线程</code> 毫无帮助，我根本就不知道这个线程生前执行了什么代码，为什么这么短命，还就因为这样的短命让 线程池 的线程暴增。</p>
<p>为了能尽最大努力解决此类问题，武器库中还得再充实一下，比如本系列要聊的 <code>Time Travel Debug</code>，即时间旅行调试。</p>
<h2 id="二-time-travel-debug">二： Time Travel Debug</h2>
<h3 id="1-什么是-时间旅行调试">1. 什么是 时间旅行调试</h3>
<p>如果说 dump 是程序的一张<strong>照片</strong>，那 TTD 就是程序的一个<strong>短视频</strong>，很显然短视频的信息量远大于一张照片，因为视频记录着疑难杂症的前因后果，参考价值巨大，简直就是银弹般的存在。</p>
<h2 id="三案例演示">三：案例演示</h2>
<h3 id="1-参考代码">1. 参考代码</h3>
<p>这是我曾经遇到的一个真实案例，在没有 TTD 的协助下最终也艰难的找到了问题，但如果有 TTD 的协助简直就可以秒杀，为了方便说明，先上一个测试代码。</p>
<pre><code class="language-C#">
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}");
}
}
</code></pre>
<p>程序跑完之后，我们抓一个dump文件，输出如下。</p>
<pre><code class="language-C#">
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 ContextDomain Count Apt Exception
0 1 12f8 00C4AF2080030220 Preemptive03C3FFAC:03C40000 00c462f8 -00001 Ukn
6 2 6a70 00C5BBD8 2b220 Preemptive03C521B8:03C53FE8 00c462f8 -00001 MTA (Finalizer)
XXXX 4 0 00C9FEB0 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
7 5 6694 00CA0990 302b220 Preemptive03C40314:03C41FE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX 6 0 00CB53B8 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 7 0 00CB5958 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 8 0 00CB4338 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 9 0 00CB4C58 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 10 0 08879278 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
8 11 5d10 08879E90 102b220 Preemptive03C2AC2C:03C2BFE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX 12 0 0887D1F8 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 13 0 0887C0D8 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 14 0 0887AB70 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 15 0 0887B400 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 16 0 0887D640 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 17 0 0887A728 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
9 18 5658 0887C520 102b220 Preemptive03C46684:03C47FE8 00c462f8 -00001 MTA (Threadpool Worker)
10 19 564 0887C968 102b220 Preemptive03C4A664:03C4BFE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX 20 0 0887AFB8 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
11 3 547c 0887A2E0 2b220 Preemptive03C50008:03C51FE8 00c462f8 -00001 MTA
</code></pre>
<h3 id="2-为什么会有很多短命线程">2. 为什么会有很多短命线程</h3>
<p>从 <code>windbg</code> 的输出看有很多的 XXX，那原因是什么呢？ 还得先观察下代码，可以看到代码会给 ThreadPool 分发 100 次任务，每个任务也就 1s 的运行时间，这样的代码会造成 ThreadPool 的工作线程处理不及继而会产生更多的工作线程，在某一时刻那些 Sleep 后的线程又会规模性唤醒，ThreadPool 为了能够平衡工作者线程，就会灭掉很多的线程，造成 ThreadPool 中的暴涨暴跌现象。</p>
<p>因果关系是搞清楚了，但对于落地是没有任何帮助的，比如线程列表倒数第二行已死掉的线程：</p>
<pre><code class="language-C#">
XXXX 20 0 0887AFB8 1039820 Preemptive00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
</code></pre>
<p>你是没法让它起死回生的，对吧？这时候就必须借助 TTD 录制一个小视频。</p>
<h3 id="3-ttd-录制">3. TTD 录制</h3>
<p>录制非常简单，选择 <code>Lauch executable (advanced)</code> 项再勾选 <code>Record</code> 即可，截图如下：</p>
<p><img src="https://img2022.cnblogs.com/blog/214741/202210/214741-20221006080823181-550513469.png"></p>
<p>等程序执行完了或者你觉得时机合适再点击 <code>Stop and Debug</code> 停止录制，截图如下：</p>
<p><img src="https://img2022.cnblogs.com/blog/214741/202210/214741-20221006080823168-1905043330.png"></p>
<p>稍等片刻，你会得到如下三个文件。</p>
<ol>
<li>ConsoleApp101.run录制文件</li>
<li>ConsoleApp101.idx录制的索引文件</li>
<li>ConsoleApp101.out日志文件</li>
</ol>
<h3 id="4-分析思路">4. 分析思路</h3>
<ol>
<li>找到 tid=20 的 OSID 线程ID</li>
</ol>
<p>因为此时的 <code>tid=20</code> 的 OSID 已经不存在了，所以用 <code>!tt</code> 在时间刻度上折半查找 <code>OSID</code> 存在的 position。</p>
<pre><code class="language-C#">
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=0023ss=002bds=002bes=002bfs=0053gs=002b efl=00000202
ntdll!RtlEnterCriticalSection+0x15:
77d8e925 f00fba3000 lock btr dword ptr ,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 ContextDomain Count Apt Exception
...
24 20 145c 0887AFB8 302b220 Preemptive03C4C1A4:03C4DFE8 00c462f8 -00001 MTA (Threadpool Worker)
</code></pre>
<p>可以清楚的看到原来是 <code>OSID =145c</code> 及<code>WindbgID=24</code> 有了这个信息不代表此时它正在执行托管方法，所以我们还需要找到这个 <code>145c</code> 是何时出生的？</p>
<ol start="2">
<li>找到当前视频中所有的 <code>ThreadCreated</code> 事件。</li>
</ol>
<p>可以在 Events 输出信息中检索 <code>id=0x145c</code> 的线程出生信息。</p>
<pre><code class="language-C#">
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)
: UID: 27, TID: 0x145C
UniqueId : 0x1b
Id : 0x145c
Lifetime :
ActiveTime :
GatherMemoryUse
</code></pre>
<p>从输出中可以看到, Lifetime 表示这个线程的一生, ActiveTime 则是从线程的Start处开始的，画个图如下：</p>
<p><img src="https://img2022.cnblogs.com/blog/214741/202210/214741-20221006080823187-1057971678.png"></p>
<p>接下来将进度条调到 <code>!tt 38B21:0</code> 处，那如何看代码进入到托管方法中呢？这个就得各显神通，我知道的有这么几种。</p>
<ol>
<li>使用单步调试</li>
</ol>
<p>先用 <code>!tt</code> 调整大致范围，然后用 p,pc,pt,t,tc,tt 微调，比如我们这篇的 <code>!tt 94</code> 就能获取到 <code>tid=20</code> 号线程的托管部分。</p>
<pre><code class="language-C#">
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=0023ss=002bds=002bes=002bfs=0053gs=002b efl=00000202
ntdll!RtlEnterCriticalSection+0x15:
77d8e925 f00fba3000 lock btr dword ptr ,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=0023ss=002bds=002bes=002bfs=0053gs=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 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()
0B1BFC1C 07b900cd System.Threading.Tasks.Task+c.<.cctor>b__272_0(System.Object)
0B1BFC24 07b90047 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0B1BFC54 07b907d2 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)
0B1BFCB8 03b9ff34 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread)
0B1BFCC8 070f7a36 System.Threading.ThreadPoolWorkQueue.Dispatch()
0B1BFD24 070ff222 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
0B1BFDB0 070e6545 System.Threading.Thread.StartCallback()
0B1BFF04 0307b9cf
</code></pre>
<ol start="2">
<li>对 compileMethod 方法下断点</li>
</ol>
<p>C# 的一个特性就是很多方法都是由 JIT 动态编译的，因为很多方法都是未编译，所以遇到编译事件的时候执行流很大概率就在托管层。</p>
<pre><code class="language-C#">
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=0023ss=002bds=002bes=002bfs=0053gs=002b efl=00000282
clrjit!CILJit::compileMethod:
502bca30 55 push ebp
</code></pre><br><br>
来源：https://www.cnblogs.com/huangxincheng/p/16756970.html
頁:
[1]