DotTrace系列：8. 时间诊断之 异步代码 和 Task任务
<h2 id="一背景">一：背景</h2><h3 id="1-讲故事">1. 讲故事</h3>
<p>现如今的很多代码都是<code>awaitasync+Task</code>的方式，对它们进行性能洞察非常有必要，awaitasync 本质上就是将状态机塞入到 Task 的 <code>m_continuationObject</code> 延续字段上，和 ContinueWith 没有本质区别，这一篇我们就来聊一聊。</p>
<h2 id="二异步和task">二：异步和Task</h2>
<h3 id="1-诊断异步代码时间">1. 诊断异步代码时间</h3>
<p>这里我就用异步读取 1G文件内容 来举例，参考代码如下：</p>
<pre><code class="language-C#">
class Program
{
static async Task Main()
{
// 创建并启动Stopwatch
Stopwatch stopwatch = new Stopwatch();
stopwatch.Start();
string filePath = @"D:\1GB_LogFile.log";
await DoRequest(filePath);
// 停止并显示总耗时
stopwatch.Stop();
Console.WriteLine($"总耗时: {stopwatch.Elapsed.TotalSeconds:F2}秒");
Console.ReadLine();
}
static async Task DoRequest(string filePath)
{
CheckParameter();
const int chunkSize = 512 * 1024 * 1024; // 每次读取512MB
try
{
Console.WriteLine("开始分块读取文件...");
int chunkCount = 0;
long totalBytesRead = 0;
using (var fileStream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.Read, 4096, FileOptions.Asynchronous))
{
byte[] buffer = new byte;
int bytesRead;
while ((bytesRead = await fileStream.ReadAsync(buffer, 0, buffer.Length)) > 0)
{
totalBytesRead += bytesRead;
chunkCount++;
// 处理当前块的数据
string chunkContent = Encoding.UTF8.GetString(buffer, 0, bytesRead);
Console.WriteLine($"读取块 {chunkCount}, 大小: {bytesRead / 1024}KB, 总计: {totalBytesRead / 1024 / 1024}MB");
}
}
Console.WriteLine($"文件读取完成，共 {chunkCount} 块");
await Task.CompletedTask;
}
catch (Exception ex)
{
Console.WriteLine($"出错: {ex.Message}");
}
}
static void CheckParameter()
{
Console.WriteLine("检查参数开始...");
Thread.Sleep(5000);
Console.WriteLine("检查参数结束...");
}
}
</code></pre>
<p>使用 dotrace 的 timeline 模式对程序进行跟踪，可以看到异步方法耗时 6.25s，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250630083423376-1385403457.png" alt="" loading="lazy"></p>
<p>接下来的问题是这 6.25s 是怎么消耗掉的呢？可以用 F5 搜索 <code>DoRequest</code> 方法的耗时，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250630083423403-1446967962.png" alt="" loading="lazy"></p>
<p>从图中可以清楚的看到如下信息：</p>
<ul>
<li>CheckParameter: 耗时 5000ms</li>
<li>continuations: 即 Task.m_continuationObject 字段中的任务，这是委托到其他线程的执行时间。</li>
<li>other: 有 Stream.ReadAsync，JIT 动态编译等等，其实就是底层状态机的部分代码块，参考如下：</li>
</ul>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250630083423397-1283666425.png" alt="" loading="lazy"></p>
<p>如何想观察这 967ms 是如何消耗掉的，可以展开一下，这里要注意一点，这里的<code>深灰色</code>展示的，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250630083423391-584470144.png" alt="" loading="lazy"></p>
<p>是不是挺有意思的。</p>
<h3 id="2-诊断task代码时间">2. 诊断Task代码时间</h3>
<p>除了异步代码会横跨多个线程，其实 Task 也有同样的场景，接下来将刚才的异步代码改成 <code>Task模式</code>，核心代码如下：</p>
<pre><code class="language-C#">
static Task DoRequest(string filePath)
{
CheckParameter();
const int chunkSize = 512 * 1024 * 1024; // 每次读取512MB
return Task.Run(() =>
{
try
{
Console.WriteLine("开始分块读取文件...");
int chunkCount = 0;
long totalBytesRead = 0;
using (var fileStream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.Read, 4096, FileOptions.Asynchronous))
{
byte[] buffer = new byte;
int bytesRead;
while ((bytesRead = fileStream.Read(buffer, 0, buffer.Length)) > 0)
{
totalBytesRead += bytesRead;
chunkCount++;
// 处理当前块的数据
string chunkContent = Encoding.UTF8.GetString(buffer, 0, bytesRead);
Console.WriteLine($"读取块 {chunkCount}, 大小: {bytesRead / 1024}KB, 总计: {totalBytesRead / 1024 / 1024}MB");
}
}
Console.WriteLine($"文件读取完成，共 {chunkCount} 块");
}
catch (Exception ex)
{
Console.WriteLine($"出错: {ex.Message}");
}
});
}
</code></pre>
<p>使用 dottrace 的 timeline 模式跟踪，拿到跟踪文件之后，使用 F5 搜索 <code>DoRequest</code> 方法，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250630083423394-1870135254.png" alt="" loading="lazy"></p>
<p>从卦中可以看到 DoRequest 方法消耗了 5010ms，根据调用栈发现没有统计到 <code>Task scheduled -> Program+<>c__DisplayClass1_0.<DoRequest>b__0()</code> 的耗时，这个就有点无语了，不像异步代码有 <code>+Continuation</code> 复选框。。。可以归到Total Time 上，这一点就比较遗憾了。</p>
<p>再说一个比较好的地方，dottrace 专门提供了一个 <code>Task</code> 复选框，它可以观测到追踪时间内程序生成了多少个Task，以及 Task 的执行时间，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250630083423389-768984498.png" alt="" loading="lazy"></p>
<p>从卦中的 <code>时间轴</code> 来看，尼玛，Task 怎么跑到 <code>Garbage Collection</code> 线程上执行，这线程是专门用来执行后台GC的，很明显这是有问题的。。。所以也不要太相信 dotTrace 哈。</p>
<h2 id="三总结">三：总结</h2>
<p>对 异步 和 Task 的下钻分析，非常有利于解决类似<code>线程饥饿</code>，<code>Task阻塞</code>等问题，希望本篇能给大家带来一点帮助。</p>
<blockquote>
<p>作为JetBrains社区内容合作者，如有购买jetbrains的产品，可以用我的折扣码 HUANGXINCHENG，有25%的内部优惠哦。</p>
</blockquote>
<img src="https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg" width="700" height="300" alt="图片名称" align="center"><br><br>
来源：https://www.cnblogs.com/huangxincheng/p/18957085
頁:
[1]