Today I will… find hidden latency across a distributed .NET application

今天我将...找出分布式 .NET 应用程序中的隐藏延迟 - Visual Studio 博客

当分布式应用程序运行缓慢时，用户只会看到一个延迟。这个延迟背后可能涉及 Web 前端、后端服务、数据库和外部 API 的多个环节。如果仅对前端进行性能分析而忽略缓慢的后端，分析工具可能会显示前端运行正常，却无法揭示真正的性能瓶颈。

本文将展示如何使用 Visual Studio 定位跨进程的性能问题：识别包含缓慢操作的进程、捕获其 CPU 活动、检查报告，并在 CPU 样本无法解释耗时情况时添加针对性的测量。GitHub Copilot Profiler Agent 通过详细分析捕获的性能数据，强化了这一工作流程，并帮助验证证据的解读。

案例研究使用了 Interview Coach 示例，这是一个包含 Blazor 前端和多个后端资源的 .NET Aspire 应用程序。最终发现的性能问题出现在 AI 流式传输路径中，但这种调查方法适用于任何分布式 .NET 应用程序，特别是用户操作需要跨进程交互的场景。

一个症状，多个进程

Interview Coach Web UI 向后端代理发送提示，并将响应以更新流的形式渲染。我使用以下提示进行测试：

Hi, I'm Peter. Here's my resume: https://justinyoo.github.io/fake-resumes/resume-peter-parker.pdf.
And this is JD: https://justinyoo.github.io/fake-resumes/jd-cloud-solution-architect.pdf

第一次完整响应耗时约 1.5 到 2 分钟。其中部分时间是预期的：首次交互需要将 PDF 解析为 Markdown 并将初始数据存储到 Cosmos DB。即使考虑到这些工作，响应速度仍感觉比预期慢。

此次交互涉及 Blazor Web UI、代理、MCP 服务器、Cosmos DB 和托管模型。在寻找缓慢方法之前，我需要先确定哪些进程在执行工作，哪些进程在等待。

Visual Studio 的性能分析器是开始调查的好地方。

在收集数据前明确问题

我将调查范围缩小到两个问题：

• 哪个进程负责交互中的缓慢部分？

• 一旦确定该进程，它是处于计算状态还是等待状态？

AppHost 会将 Web UI、代理、MCP 服务器和数据服务作为独立进程启动。对 InterviewCoach.AppHost 的性能分析描述了协调器。它不会自动描述 InterviewCoach.WebUI 中的 Blazor 代码。

CPU 使用情况可以从多个进程中收集，这对于初步的系统级视图很有用。在此案例中，可见的延迟发生在 Web UI 消耗和渲染更新时，因此我需要对该进程进行有针对性的捕获。我将后端资源保留在 Aspire 中，并将 Web UI 作为 Visual Studio 的性能分析目标启动。

独立的 Web UI 需要一个启动配置，使用自己的端口并将服务发现指向正在运行的代理。在此示例中，代理的 HTTPS 端点使用了 7048 端口。Aspire 在重启后可能会分配不同的端口，因此请使用仪表板中显示的值。

在 src/InterviewCoach.WebUI/Properties/launchSettings.json 的 profiles 部分下添加一个 Profiler 配置：

"Profiler": {
  "commandName": "Project",
  "dotnetRunMessages": true,
  "launchBrowser": true,
  "applicationUrl": "https://localhost:7201;http://localhost:5088",
  "environmentVariables": {
    "ASPNETCORE_ENVIRONMENT": "Development",
    "Services__agent__https__0": "localhost:7048"
  }
}

Web UI 通过逻辑服务名称访问代理：

client.BaseAddress = new Uri("https+http://agent");

环境变量映射到 Services:agent:https:0。基于配置的服务发现提供程序会将 localhost:7048 解析为代理的 HTTPS 端点。该值包含主机和端口，不包含 https:// 前缀。

在 Visual Studio 中：

• 将 InterviewCoach.WebUI 设置为启动项目。
• 选择 Profiler 启动配置。
• 将构建配置设置为 Release。
• 打开 Debug > Performance Profiler，或按 Alt+F2。
• 确认目标为 InterviewCoach.WebUI。
• 选择 CPU 使用率。
• 选择暂停收集后启动。

启动应用程序。当 Web UI 准备就绪后，恢复收集，提交测试提示，并在响应完成时停止收集。

在询问 Copilot 之前阅读 CPU 报告

从 CPU 时间线开始。仅选择从提交提示到接收到最终更新的区间。这会从图表下方的详细信息中移除启动过程和无关活动。

接下来打开调用树并启用 Just My Code。各列回答不同问题：

• Total CPU 包括方法及其所有调用的 CPU 样本。
• Self CPU 包括直接归因于该方法的样本。

使用 Expand Hot Path 跟随最消耗 CPU 的分支，然后搜索 GetStreamingResponseAsync 以找到 Web UI 的流式传输路径。Functions 视图也适用于按 Total CPU 或 Self CPU 对应用程序方法进行排序，而无需遍历整个树。

在此捕获中，所选区间报告了 6.7% 的 CPU 使用率，调用树未显示导致长时间响应的主导应用热点路径。这并未证明延迟的原因，但告诉我一个更具体的信息：在所选区间内，Web UI 并未受到 CPU 限制。

这一区别很重要。CPU 使用率样本记录活跃的处理器工作。等待 I/O、计时器、锁或其他服务所花费的时间会使用户等待，但不会显示为 CPU 热点路径。在没有解释经过时间的 CPU 热点路径时，下一步是检查流式传输路径上的代码是否存在显式等待。

跟随证据进入流式传输循环

src/InterviewCoach.WebUI/Components/Pages/Chat/Chat.razor 中的响应循环包含了一个有用的线索：

await foreach (var update in ChatClient.GetStreamingResponseAsync(
    outboundMessages,
    chatOptions,
    cancellationToken))
{
    await Task.Delay(50);

    messages.AddMessages(update, filter: c => c is not TextContent);

    if (update.Role == ChatRole.Assistant)
    {
        responseText.Text += update.Text;
        ChatMessageItem.NotifyChanged(responseMessage);
    }

    StateHasChanged();
}

这行代码会暂停每个流式传输更新：

await Task.Delay(50);

如果在200次更新后收到响应，理论累计延迟为10秒：

200次更新 × 50毫秒 = 10,000毫秒

该延迟似乎在UI刷新前对更新进行节流。无论添加它的原因是什么，其成本会随着更新次数的增加而线性增长。

测量累计等待时间

CPU使用率无法衡量等待Task.Delay所消耗的时间。为了捕获该值，在Chat.razor中添加@using System.Diagnostics，并在现有循环周围添加临时计数器：

var responseTimer = Stopwatch.StartNew();
var measuredDelay = TimeSpan.Zero;
var updateCount = 0;

await foreach (var update in ChatClient.GetStreamingResponseAsync(
    outboundMessages,
    chatOptions,
    cancellationToken))
{
    updateCount++;

    var delayStarted = Stopwatch.GetTimestamp();
    await Task.Delay(50);
    measuredDelay += Stopwatch.GetElapsedTime(delayStarted);

    // 现有的更新处理逻辑...
}

Logger.LogInformation(
    "流式传输在 {ElapsedMs} 毫秒内完成，共 {UpdateCount} 次更新； "
    + "人工延迟消耗了 {DelayMs} 毫秒",
    responseTimer.Elapsed.TotalMilliseconds,
    updateCount,
    measuredDelay.TotalMilliseconds);

代码在响应完成后记录一次日志：

流式传输在 {{ 总耗时 }} 毫秒内完成，共 {{ 流式更新次数 }} 次更新；人工延迟消耗了 {{ 测量延迟时间 }} 毫秒

这些是流式更新，不是模型标记。一次响应更新不一定代表一个标记。

Task.Delay(50) 保证的是最小等待时间，而不是精确的恢复时间。线程调度和其他工作可能会使测量的间隔超过50毫秒。

我用相同的提示运行了五次。

移除延迟并重复

为了进行比较，我移除了 await Task.Delay(50) 并再次运行了相同的提示五次。我暂时保留了时间戳调用，因此两种版本生成了相同的日志格式。由于它们之间没有等待延迟，这些调用仅测量了仪器开销。

实时模型在每次运行时可能产生不同的响应和更新次数。因此，总响应时间包括模型和网络的差异。这是有用的用户体验上下文，但延迟计数器是隔离Web UI人工等待的测量指标。

使用Profiler Agent深入分析

在阅读报告并测量了疑似等待时间后，我启动了GitHub Copilot Profiler Agent，以更详细地分析CPU会话并验证我的解释。我提供了要调查的方法和计数器值：

@Profiler 请审查InterviewCoach.WebUI的CPU使用情况会话。响应包含193个流式更新，耗时84,813.9868毫秒，在Task.Delay(50)内部累计约11,871毫秒，即每个更新约61.5088毫秒。报告中显示GetStreamingResponseAsync有显著的CPU工作量，还是经过时间与异步等待一致？

这个问题是刻意保持狭窄的。Profiler Agent可以帮助解释报告，但CPU分析本身无法单独测量经过的等待时间。

Profiler Agent得出了相同的结论：响应处理不是CPU密集型的。直接计时器仍然是累计延迟的证据。

测量结果说明

基线（含Task.Delay(50)）

运行次数

总耗时（毫秒）

更新次数

预期延迟（毫秒）

测量延迟（毫秒）

延迟/更新（毫秒）

1

92386.3482

168

8400

10299.8094

61.3084

2

84772.6630

188

9400

11549.6042

61.4341

3

90705.5531

153

7650

9376.8390

61.2865

4

79027.4327

147

7350

9028.3215

61.4172

5

69061.6113

190

9500

11714.1005

61.6532

AVG

83190.7217

169

8460

10393.7349

61.4199

MED

在人工延迟期间，五次运行的耗时在9.03到11.71秒之间。累积延迟的中位数为10.30秒。

测量的更新间隔平均为61.42毫秒，比标称的50毫秒长约11毫秒。累积等待时间，而非50毫秒与61毫秒之间的差异，才是性能问题所在。

### 移除Task.Delay(50)后

测量的计时器开销（毫秒）

每更新开销（毫秒）

98450.7463

226

0.0262

0.0001

69886.9730

174

0.0155

77264.4819

289

0.0256

58254.1312

163

0.0171

86431.5633

164

0.0257

0.0002

78057.5791

203

0.0220

表格中测量的微小间隔是时间戳开销。它们不代表模型、网络、渲染或端到端处理时间。

总响应时间中位数从84.77秒降至77.26秒，相差约7.51秒。该对比不是受控基准测试，因为实时模型产生了不同的响应和更新次数。直接结果更简单：移除该行代码消除了基准测试中测量到的9到12秒应用附加等待时间。

## 移除等待，而非数据流

只有在分析器定位到包含代码的进程后，性能分析才有效。AppHost有助于协调代理及其依赖项，而独立的Web UI为Visual Studio提供了明确的性能分析目标。

CPU使用率回答了问题的一部分：捕获的响应未主要由应用CPU工作主导。它无法暴露累积的异步等待，因此Task.Delay(50)周围的直接计时器提供了缺失的证据。

测量结果不支持在每次更新中保留无条件的50毫秒延迟。移除延迟后响应仍然会流式传输。如果UI需要有意的节奏控制，该行为应单独设计和测量，而不是将延迟与输入更新数量绑定。

一个选项是立即处理更新但合并UI刷新。此示例每50毫秒最多渲染一次并始终刷新最终更新：

 /think

// 限制UI刷新频率，最多每50毫秒一次，同时不延迟流数据的消费。 var renderInterval = TimeSpan.FromMilliseconds(50); var lastRenderAt = Stopwatch.GetTimestamp(); var renderPending = false; var textChanged = false;

try { await foreach (var update in ChatClient.GetStreamingResponseAsync( outboundMessages, chatOptions, cancellationToken)) { messages.AddMessages(update, filter: c => c is not TextContent); renderPending = true;

if (update.Role == ChatRole.Assistant && !string.IsNullOrEmpty(update.Text)) { responseText.Text += update.Text; textChanged = true; }

// 当渲染间隔时间已过时，刷新待处理的UI更改。 if (Stopwatch.GetElapsedTime(lastRenderAt) < renderInterval) { continue; }

FlushRender(); lastRenderAt = Stopwatch.GetTimestamp(); } } finally { FlushRender(); }

void FlushRender() { if (!renderPending) { return; }

if (textChanged) { ChatMessageItem.NotifyChanged(responseMessage); }

StateHasChanged(); renderPending = false; textChanged = false; }

与Task.Delay(50)不同，这种方法不会暂停每个传入的更新。突发的更新会被合并为更少的渲染次数，而较慢的更新仍会按到达时间显示。50毫秒的刷新间隔只是一个起点，而非固定建议；需要根据预期的流速进行性能分析，并根据响应速度和渲染成本进行调整。这种合并后的版本未包含上述测量，因此需要单独进行前后对比测试。

孤立来看，50毫秒似乎成本很低。但当它在真实响应中重复出现时，会累积产生约10秒的可避免等待时间。

## 参考资料

- .NET中的服务发现

- 使用CPU性能分析进行性能分析

- 使用GitHub Copilot Profiler Agent分析应用程序

.entry-content

AI免责声明