使用 Cloud Monitoring 和 OpenCensus 确定导致应用延迟的原因

Last reviewed 2019-08-28 UTC

本文档旨在帮助您使用 OpenCensus 和 Monitoring 来监控指标和分布式跟踪记录，从而为应用开发者确定尾延迟时间的原因。

观察您的应用为用户提供的服务情况后，您会发现有些用户的应用延迟时间比其他用户更长。这种差异会随着用户的多样性和资源使用率的提高而扩大。通过确定长延迟时间的原因并予以解决，您可以扩大用户群并获得最佳的资源使用率。如果您提高资源使用率，则由于资源争用的原因，尾延迟时间现象会最先表现出来。

虽然遇到这些较长延迟时间现象的用户数量可能很少，但这些用户也可能是重要的用户，例如，如果他们代表了新兴潜在市场的先行者。

本文档讨论了如何确定和解释这些用户遇到的长延迟时间的原因。具体而言，本文档回答了以下问题：

如何准确测量尾延迟时间？
导致应用延迟时间的主要原因是什么？
如何评估用于最大程度缩短尾延迟时间的策略？

回答这些问题的主要主题如下：

确定监控指标估算值不准确的原因。
确定导致长延迟时间的原因。
最大程度地缩短尾延迟时间。

GitHub 代码库中提供了测试应用的源代码。

本文档假定您熟悉 OpenCensus、Cloud Monitoring、Cloud Trace、BigQuery 的基本用法，并且熟悉如何使用 Java 开发应用。

术语

指标: 应用性能的量度。
延迟时间: 应用执行任务所需的时间。本文档中的延迟时间值是从应用的代码中测量的。
尾延迟时间: 一小部分用户遇到的较长延迟时间值。尾延迟时间可以在百分位级别定义。例如，第 99 百分位是在某个时间段内测量到的请求的最长 1% 延迟时间值。如需了解详情，请参阅站点可靠性工程的“监控分布式系统”一章中的“担心您的尾延迟时间”一节。
聚合模型: 监控指标的表示法，用于显示所收集测量结果的统计分布。本文档假设了一个直方图模型，其中延迟时间范围划分为各个区段，每个时间间隔记录了每个区段的计数。Monitoring 使用术语“分布指标”来代表具有这种表示法的指标。

背景

云应用所有者通常会监控中间延迟时间值和尾延迟时间值的组合。中间延迟时间是衡量应用整体运行状况的良好指标。不过，随着您的应用纵向扩容，可能会出现细微的问题，这些问题无法通过中间延迟时间轻松观察到。

对于许多用途来说，了解尾延迟时间可能很有用：

尽早检测出在中间延迟时间中不明显的新出现的问题。
确保不以对某些请求的非最佳处理为代价来实现高利用率。
当单个服务器运行状况不佳或只有少数用户遵循的代码路径没有得到正确处理时，监控机群。
告知用于最大程度缩短尾延迟时间的策略，例如为超时和退避重试设置适当的值。您可以将超时调整为略高于第 99 百分位延迟时间，以放弃连接并重试，而不是将请求打开较长时间。

导致尾延迟时间的原因可能有很多。典型原因如下：

请求载荷大小的变化
高 CPU 利用率
非最佳应用代码结构
网络调用路由距离的变化
服务器偶尔会意外地重新启动，相关的连接会断开，系统会冷启动
缓冲或排队
连接管理，例如重新建立过时的连接
网络拥塞，包括数据包丢失
导致暂停处理用户请求的数据垃圾回收或压缩
云服务延迟时间的变化
非最佳的连接超时设置

确定延迟时间原因的策略包括：

确定准确的延迟时间测量方法：由于尾延迟时间从定义上来说仅占流量的一小部分，因此您需要了解测量结果的准确度。
实现监控、跟踪和日志记录解决方案：通过使用 OpenCensus 和 Monitoring，应用会为请求创建根 span 跟踪记录，以包含不同测量结果的子 span。然后，系统会通过 OpenCensus HTTP 集成自动生成子 span，并添加日志集成跟踪记录以记录额外的上下文。这样可以最大程度地减少监控和跟踪所需的额外代码。
探索数据：查看显示长时间运行请求尾延迟时间的报告和图表，并确定哪些子 Span 执行时间最长。
确定尾延迟时间的原因：收集相关来源的信息，这些信息可帮助解释长时间运行的子 span 的原因，并将其与示例 span 中的注释进行比较。
了解更详细的查询：将日志导出到 BigQuery 并将其与跟踪记录信息相结合，以深入分析并量化应用行为。

本文档中讨论的分析是对使用 Cloud Storage 和微服务横向扩容的高流量系统进行分析的结果。导致尾延迟时间易变的主要原因是测量误差、载荷大小、云服务中的可变延迟时间，以及托管应用的虚拟机上的负载。

云用户可以选择使用库中所含预建集成的指标、来自云提供商的受支持指标以及自定义指标。预建集成的指标示例包括 OpenCensus 的 gRPC、HTTP、SQL 集成。Google Cloud 包含大量受支持的指标，这些指标通过 Monitoring 公开。另一种方法是为额外的自定义指标（通常是计时器和计数器）开发代码。比较这三种来源的时间序列是分析微服务和应用数据存储的延迟时间原因的一项常见任务。

测试应用概览

测试应用模拟尾延迟时间问题，并且与 OpenCensus 和 Monitoring 集成，以演示确定问题所需的工具和方法。GitHub 项目中提供了源代码、构建文件和说明。示例应用是使用 Java 编写的，但您可以将本文档应用于其他语言。如需详细了解 HTTP 请求的 OpenCensus 插桩 (instrumentation)，请参阅适用于 Java 的 Jetty 集成和适用于 Go 的 Jetty 集成。测试应用基于此 GitHub 示例代码。

以下是该应用的示意图。

与 Cloud Storage 和 Compute Engine 上的服务器应用通信的客户端应用的架构图。

客户端应用与 Cloud Storage 和 Compute Engine 实例上托管的服务器端应用进行通信。

以下是一个典型的请求流程：

Cloud Storage API 从客户端应用中的 Cloud Storage 检索 JSON 文件。
该文件的内容会发送到服务器。
服务器对客户端发送的数据进行一些处理，以模拟真实应用占用的时间和资源。
HTTP 响应会发回给客户端。
客户端会执行下游处理。此时，测试应用会用简单的算法来代替业务逻辑。

在启动时，应用会初始化以下内容：

客户端 Java Util Logging (JUL)，用于导出包含跟踪记录 ID 的 Cloud Logging。服务器会使用 logback 日志记录附加器来实现跟踪记录与日志的关联。
OpenCensus HTTP 指标视图已注册。OpenCensus 的适用于 Java 的 HTTP 集成包含许多关于延迟时间、HTTP 响应代码以及发送和接收的字节数的指标视图。
OpenCensus Monitoring stats 导出器会在后台线程中将聚合指标发送到 Monitoring。
OpenCensus Monitoring 跟踪记录导出器会在后台线程中将跟踪记录 span 发送到 Monitoring。
Cloud Storage 客户端 API 会下载用于 HTTP 载荷的文件。
系统会创建一个应用线程池，以便将负载推送到应用。与单个线程相比，多个线程可以将更高的负载推送到服务器。

系统会按照以下步骤收集和处理 Monitoring 指标和跟踪记录数据：

OpenCensus 库会收集指标和跟踪记录数据。
OpenCensus 会定期聚合指标数据并将其导出到 Monitoring。跟踪记录数据会在没有聚合的情况下导出到 Trace。
OpenCensus 会将跟踪记录 ID 添加到 Cloud Logging 条目。日志条目会导出到 Cloud Logging 服务。

您可以将使用 OpenCensus 收集的指标导出到多个后端监控系统，这些系统提供存储、分析、可视化和提醒功能。每个系统都有不同的数据表示格式。本文档重点介绍 Monitoring。

聚合监控指标的准确性

OpenCensus 和 Monitoring 提供了可用于监控应用性能的工具。为避免错误地判断图表中的线条，您需要了解它们是如何创建的，尤其是对于表示尾延迟时间的线条，例如第 99 百分位 (p99)。以下部分介绍了聚合指标数据的限制。

Monitoring 中的指标时间序列表示法

Monitoring 会根据数值间隔的区段边界计算分布指标的延迟时间百分位。此方法是 Monitoring 和 OpenCensus 使用的一种常用方法，其中 OpenCensus 会表示指标数据并将其导出到 Monitoring。Cloud Monitoring API 的 TimeSeries.list 方法会返回项目和指标类型的区段计数和边界。您可以在 Cloud Monitoring API BucketOptions 对象中检索区段边界；您可以在 API Explorer 中针对 TimeSeries.list 试验该对象。

如需在 API Explorer 中过滤 OpenCensus HTTP 客户端延迟时间，您可以使用以下过滤条件：

resource.type=global metric.type="custom.googleapis.com/opencensus/opencensus.io/http/client/roundtrip_latency"

结果包括数据点对象数组。以下示例显示了区段的方案和区段计数：

"points": [ {
  "interval": { "startTime": "2019-02-14T18:11:24.971Z",
                "endTime": "2019-02-14T18:33:35.541Z" },
  "value": {
    "distributionValue": {
...
    "explicitBuckets": {
      "bounds": [0, 1, 2, 3, 4, 5, 6, 8, 10, 13, 16, 20, 25, 30, 40, 50, 65, 80, 100, 130, ...] }
              },
      "bucketCounts": [0, 0, 0, 0, 0, 14, 17, 164, 3, 0, 1, 0, 0, 0, 0, ...]
}}]

您在 Monitoring 图表中看到的每个点（表示延迟时间值）都来自于一个分布。您可以使用增长因数来定义区段，而不是为每个区段定义边界。例如，增长因数 2.0 表示区段边界为 0-1、1-2、2-4、4-8 等等。如需详细了解 Monitoring 指标，请参阅指标类型的结构。

您可以修改图表以显示第 50 百分位（中间延迟时间）、第 95 百分位和第 99 百分位的延迟时间，从而显示以下折线图。

显示第 50 百分位、第 95 百分位和第 99 百分位的尾延迟时间图表。

如需了解用于计算这些百分位值的数据，请添加热图图表类型。当聚合器 (Aggregator) 设置为求和时，系统会显示以下客户端延迟时间热图。

尾延迟时间的热图图表。

热图是一种显示由 Monitoring 存储的分布数据的方法。热图的区域与使用 REST API 检索的区段边界相对应。您可以将指针悬停在热图的区域上，以了解某个时间段内任何给定区段中包含的点数。用于计算折线图中百分位值的数据很稀疏。

如果您希望获得更准确的延迟时间测量结果，可以采用以下几种策略：

添加更多数据。您可以在实验中生成更多数据，但生产应用的流量可能不够高。
缩小区段并更改边界以更好地适应您的数据。如果您要创建自己的自定义指标，则可以使用此方法。但是，如果您使用来自预建 OpenCensus 集成的数据或 Google Cloud 从其后端服务收集的数据，则可能无法进行这些调整。OpenCensus 集成的区段边界由“视图”中 OpenCensus 集成的实现者决定。例如，HTTP 客户端延迟时间区段边界在 HttpViewConstants.java 类中定义。同样，Google Cloud 指标也是在 Monitoring 内部定义的。
请对尾延迟时间百分位使用跟踪记录或日志（而不是指标数据）。本文档的后续部分将介绍这些选项。

模拟数据

您可以将聚合模型的准确度与从随机分布中提取的原始模拟数据进行比较，以了解区段边界可以产生多大的差异。在此示例中，Beta 版分布对真实延迟时间值的典型偏斜分布进行了建模。这是由一个连续随机变量（没有小于零的值）、一个明显峰值和一个较长递减尾部构成的分布。Beta 版分布使用 NumPy 的 random.beta 函数和参数 a = 2, b = 5，并乘以常数因子 70 来模拟中间延迟时间值为 18.5 毫秒的实际延迟时间值。该模拟包括 GitHub 项目所含的 Colab 工作表 tail_latency_lab.ipynb 中 Beta 版分布的 100000 个随机值。

下图显示，growthFactor = 2.0 的区段间隔太稀疏，无法提供准确的尾延迟时间估算值。

显示增长因数为 2.0 的聚合模型。

图表上的线性轴显示了随机分布的预期形状。下图显示了 growthFactor = 1.4 的区段边界。

显示增长因数为 1.4 的聚合模型。

下图显示 growthFactor = 1.2 的区段边界更接近预期的形状，但在该分布的高端部分仍有点粗略。

显示增长因数为 1.2 的聚合模型。

下表显示了基于区段分布的估算值与基于原始值的计算结果的对比。

分布	中间延迟时间	第 99 百分位
原始	18.5	49.5
增长因数 2.0	19.2	62.0
增长因数 1.4	18.7	53.9
增长因数 1.2	18.6	51.1

在此示例中，若要提供第 99 百分位延迟时间的合理准确估算值，则需要使用增长因数 1.2。在 OpenCensus 导出器中，您可以将值从原始值转换为采样分布。创建 OpenCensus 视图时，您可以配置区段边界。视图包含一个 Aggregation 对象。如需了解详情，请参阅 Java 文档或 Go 文档。

使用 OpenCensus 对 HTTP 延迟时间进行的测量

在测量 HTTP 延迟时间的时候，您需要测量客户端与服务器之间发送和接收 HTTP 请求的时间，并记录结果。通过创建 OpenCensus Tag 或使用 HTTP 客户端的预建集成，您可以在代码中实现此操作。HTTP 集成适用于 Go 和 Go HTTP 软件包，以及 Java 和 Jetty HTTP 客户端。使用 OpenCensus HTTP 集成的优势在于，您不必为要收集的每个指标添加 Tag 对象。

确定造成延迟时间的原因

之前介绍的测试应用对自身产生了压力，导致尾延迟时间增加。本文演示了以下问题：

偶尔有大型载荷
高 CPU
短超时
带有重试的应用代码路径中的变化

以下部分介绍了如何检测和量化这些问题。

大型载荷的影响

为了调查载荷大小的影响，以下代码随机增加了发送的 20 个 HTTP 请求当中 1 个请求的载荷大小：

client/src/main/java/com/google/cloud/solutions/opencensus/client/TestInstrumentation.java

在 GitHub 上查看

static byte[] getContent(String bucket) {
  BlobId blobId = null;
  int n = rand.nextInt(100);
  if (n >= 95) {
    blobId = BlobId.of(bucket, LARGE_FILE);
  } else {
    blobId = BlobId.of(bucket, SMALL_FILE);
  }
  return storage.readAllBytes(blobId);
}

当您在跟踪记录列表中查看较长延迟时间请求的跟踪记录时，这些跟踪记录可能与较大的载荷大小相关。

显示较长延迟时间请求的跟踪记录列表。

如果您点击显示事件，则可以查看有关已发送和已接收载荷的更多详细信息。如果有较长的延迟时间，则表示载荷较大。

由于以下原因，Cloud Trace 在确定延迟时间方面优于 Monitoring：

Trace 会提供请求的延迟时间值，而不是聚合值。
Trace 会提供请求的载荷大小。

高 CPU 利用率的影响

高 CPU 利用率可能会因并发处理而造成尾延迟时间增加，这可能导致资源争用以及后续的 CPU 排队处理请求。Monitoring 会提供 CPU 利用率作为 Compute Engine 实例的内置指标之一。但是，在运行性能测试或调查性能问题时，我们建议您安装 Monitoring 代理，因为它提供了更多操作系统和开源指标，包括内存、磁盘使用情况以及能够显示资源争用不同类型的其他指标。如需了解详情，请参阅代理指标列表。

由于自动扩缩功能的原因，管理服务器应用的 CPU 利用率比管理客户端应用的 CPU 利用率更容易。在 Compute Engine 上，代管式实例组可以根据平均 CPU 利用率、负载平衡服务容量、Monitoring 指标和时间表使用自动扩缩政策。自动扩缩器会添加虚拟机来适当调整机群大小以处理负载。客户端 CPU 利用率可能更难持续管理，并且可能影响延迟时间的测量，因为系统必须从网络读取载荷并对其进行反序列化，这需要利用 CPU。由于客户端应用对延迟时间的反应在较大程度上决定了用户体验，因此本文档重点介绍这种类型的延迟时间。

监控比跟踪更适合用于确定高 CPU 利用率的影响，因为高 CPU 利用率通常不是一个 HTTP 请求的结果。以下示例使用测试应用同时运行多个执行器线程并在 g1-small 虚拟机上运行客户端代码，从而调查 CPU 利用率的影响。然后，我们将 CPU 利用率和延迟时间与 n1-standard-1 vCPU 虚拟机上运行的客户端应用中的值进行比较。

下图显示了实验的中间延迟时间和第 95 百分位的端到端延迟时间。通过移除请求之间的 sleep 语句，请求率在凌晨 3:21 提高了，从而显示 CPU 利用率大幅提高时的延迟时间差异。GitHub 代码库中提供了用于创建虚拟机以及运行测试的命令。

按实例 ID 显示的中间延迟时间图表。

上图显示了负载实验期间客户端和服务器的中间延迟时间。请注意 3:21 时（此时负载增加了）的延迟时间增加现象。下图显示了同一测试期间第 95 百分位的延迟时间。

按实例 ID 显示的第 95 百分位延迟时间图表。

下图显示了此次测试的 CPU 利用率。该图表中的 CPU 利用率在 3:21 也提高了。

Compute Engine 实例的 CPU 利用率图表。

提高请求率会影响延迟时间，但与 CPU 利用率不成比例。令人惊讶的是，具有 1 个 vCPU 的实例和小型实例的延迟时间是一致的，即使小型实例在 CPU 利用率大约为 78% 的情况下运行也是如此。此结果表明，您可以在 CPU 利用率较高的情况下运行机群。请注意，此测试并不用于基准化分析研究，您的结果可能会在应用实现期间发生变化。

Cloud Profiler 是一款用于调查 CPU 耗用量较高的实例的有用工具。

应用代码分支和参数值造成的延迟时间

日志记录可以帮助您解决最困难的应用延迟时间问题。本部分演示了如何合并日志和跟踪记录数据，以调查受不同代码路径和参数值影响的延迟时间问题。日志跟踪记录方法可避免在代码中添加大量计时语句。基于微服务的应用的常见问题在于管理超时和重试。长时间的超时可能会导致糟糕的用户体验；如果长时间的超时阻碍了过多连接，则应用可能会停止运行。我们建议您设置较短的超时，稍等片刻，然后重试。但是，频繁的重试可能会导致重试次数暴增并导致突发事件恢复困难。您应该按照以下原则来设置超时：只有一小部分（例如少于 1%）请求需要重试。但是，测试应用会将重试时间设置为测试服务器的 HTTP 请求的低值，以演示重试在起作用，而不必等待真实的中断现象出现。

适用于 Cloud Storage 的 Google API 客户端库中也实现了重试，因此您无需在自己的代码中实现重试。如需详细了解指数退避算法，请参阅截断的指数退避算法。

借助 OpenCensus 监控日志关联集成，您可以从跟踪记录中查看日志条目。此集成使用 Cloud Logging Enhancer 将跟踪记录信息添加到日志中。通过设置适用于 Java 的 Logging 并将 opencensus-contrib-log-correlation-stackdriver1 Maven 依赖项添加到您的构建中，您可以将此集成添加到您的应用中。在撰写本文档时，与 Go 的日志集成尚未实现，但您可以请求增加该功能。针对 Go 的当前替代方案是向跟踪记录 span 添加带有所需信息的注释。

测试应用中用于准备、发送和处理微服务请求的方法如下所示：

client/src/main/java/com/google/cloud/solutions/opencensus/client/JettyTestClient.java

在 GitHub 上查看

private void prepareSendProcess(
    HttpClient httpClient,
    HttpMethod method,
    Function<Integer[], Integer> downStreamFn,
    String fnName)
    throws InterruptedException {
  Tracer tracer = Tracing.getTracer();
  try (Scope scope = tracer.spanBuilder("main").startScopedSpan()) {
    StopWatch s = StopWatch.createStarted();
    byte[] content = new byte[0];
    if (method == HttpMethod.POST) {
      content = TestInstrumentation.getContent(testOptions.bucket());
    }
    byte[] payload = sendWithRetry(httpClient, method, content);
    TestInstrumentation.processPayload(payload, downStreamFn, fnName);
    TestInstrumentation.recordTaggedStat(
        method.toString(), s.getTime(TimeUnit.NANOSECONDS) / 1.0e6);
  }
}

该方法会创建一个限定范围的 span 作为请求的顶级跟踪记录，该 span 涵盖所有准备阶段、将 HTTP 请求发送到服务器以及下游处理的代码。prepareSendProcess 方法会调用 sendWithRetry，后者会使用重试机制封装 HTTP 请求：

client/src/main/java/com/google/cloud/solutions/opencensus/client/JettyTestClient.java

在 GitHub 上查看

private byte[] sendWithRetry(HttpClient httpClient, HttpMethod method, byte[] content)
    throws InterruptedException {
  ExponentialBackOff backoff = new ExponentialBackOff.Builder()
    .setInitialIntervalMillis(500)
    .setMaxElapsedTimeMillis(5*60*1000)
    .setMultiplier(2.0)
    .setRandomizationFactor(0.5)
    .build();
  for (int i = 0; i < MAX_RETRIES; i++) {
    try {
      return sendRequest(httpClient, method, content);
    } catch (RetryableException e) {
      LOGGER.log(Level.WARNING, "RetryableException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (InterruptedException e) {
      LOGGER.log(
          Level.WARNING, "InterruptedException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (TimeoutException e) {
      LOGGER.log(Level.WARNING, "TimeoutException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (ExecutionException e) {
      LOGGER.log(Level.WARNING, "ExecutionException attempt: " + (i + 1) + " " + e.getMessage());
    }
    try {
      Thread.sleep(backoff.nextBackOffMillis());
    } catch(IOException e) {
      throw new RuntimeException("MaxElapsedTime exceeded");
    }
  }
  throw new RuntimeException("Max retries exceeded");
}

以下方法会发送 HTTP 请求：

client/src/main/java/com/google/cloud/solutions/opencensus/client/JettyTestClient.java

在 GitHub 上查看

private byte[] sendRequest(HttpClient httpClient, HttpMethod method, byte[] content)
    throws InterruptedException, TimeoutException, ExecutionException, RetryableException {
  String targetURL = testOptions.targetURL();
  HttpRequest request = (HttpRequest) httpClient.newRequest(targetURL).method(method);
  if (request == null) {
    throw new RetryableException("Request is