3

我试图更好地了解 Google 的 Cloud Console Stackdriver Trace 显示调用详细信息的方式，并为我的应用调试一些性能问题。大多数请求都与 memcache 设置/获取操作密切相关，我在这里遇到了一些问题，但我不明白为什么调用之间有很长的时间间隔。我上传了 2 张截图。

调用@1025ms 呼叫@5235ms

因此，如您所见，调用 @1025ms 花费了 2ms，但它与 urlfetch 调用 @5235ms 之间的时间超过了 4 秒。

首先，我的代码在这一点上并不密集（完整的请求显示大约 9000 毫秒的未跟踪时间），其次，运行相同代码的大多数类似请求没有这些差距（即重复请求不会具有相同的行为）。但我在其他请求上也看到了这个问题，我无法重现它们。

请指教！

编辑：

我从 appstats 上传了另一个屏幕截图。这是一个“正常”的请求，通常需要几百毫秒才能运行（最多 1 秒），并且在 localhost（开发）中也是如此。我无法找到任何进一步调试的东西。我觉得我错过了一些简单的东西，一些基本的东西，关于应用程序引擎的 DO 和 DO NOT。

应用统计

4

2 回答 2

2

我知道导致此类差距的以下常见原因（“未追踪时间”）：

  • 在这些间隙期间，请求实际上受 CPU 限制。

    要检查此问题，请转到日志查看器并查看受影响的传入 HTTP 请求的详细信息。请注意，从跟踪详细信息到日志条目还有一个方便的直接链接。在请求日志条目中，查找cpu_ms字段，该字段指出

    完成请求所需的 CPU 毫秒数。这是 CPU 实际执行应用程序代码所花费的毫秒数，以基准 1.2 GHz Intel x86 CPU 表示。如果实际使用的 CPU 比基线快，则 CPU 毫秒数可能大于实际时钟时间 [..]。（文档）。

    该指标在protoPayload.megaCycles中也可用。

    这是一个慢速请求的示例日志条目，其中包含大量未跟踪时间：

    2001:... - - [02/Mar/2017:19:20:22 +0100] "GET / HTTP/1.1" 200 660 - "Mozilla/5.0 ..." "example.com" ms=4966 **cpu_ms=11927** cpm_usd=7.376e-8 loading_request=1 instance=... app_engine_release=1.9.48 trace_id=...

    对于此示例请求， cpu_ms字段异常高 ( 11927 )，表明大部分未跟踪的时间都花在了应用程序本身（或运行时）中。

    为什么请求处理程序使用那么多 CPU？通常，几乎不可能准确地知道 CPU 时间用在了哪里，但是如果您知道在给定请求中应该发生什么，您可以更轻松地缩小范围。两个常见的原因是：

    • 这是对新启动的 App Engine 实例的第一个请求。JVM 需要加载类和 JIT 编译热方法——这预计会显着影响第一个请求（可能还会影响更多）。在请求日志条目中查找loading_request=1以检查您的请求是否因此而变慢。考虑配置预热请求以提高性能。

      Protip，如果您想在日志查看器中集中您的调查过滤掉此类加载请求，请应用此高级过滤器：

      protoPayload.megaCycles > 10000 and protoPayload.wasLoadingRequest=false

    • 由于过度使用反射，应用程序代码的某些部分大大减慢了速度。这特定于 App Engine 标准环境，其中安全管理器限制反射的使用。唯一的缓解是使用更少的反射。请注意，App Engine 服务基础架构在不断发展，因此该提示可能迟早会过时。

      如果问题在开发应用程序服务器中可以本地重现，您可以使用分析器（或者可能只是 jstack）来缩小范围。在其他一些情况下，我实际上不得不逐步平分应用程序代码、添加更多日志语句、重新部署等，直到识别出有问题的代码。

  • 实际上，在 App Engine 标准环境中，Stackdriver Trace 未涵盖对后端的未跟踪调用。到目前为止，我知道的唯一示例是 Cloud SQL。考虑使用Google Cloud Trace for JDBC来跟踪与 Cloud SQL 的交互。

  • 该应用程序是多线程的（太棒了！）并且遇到了一些自己造成的同步问题。我在野外看到的例子：

    • 特定于应用程序的同步会强制对存储后端的所有请求进行序列化（对于给定的 App Engine 实例）。痕迹中没有任何东西突出，除了那些神秘的缝隙……
    • 该应用程序使用数据库连接池。并行请求的数量超过了池的容量（对于给定的 App Engine 实例），一些请求必须等到连接可用。这是上一项的更复杂的变体。
于 2017-03-02T22:38:07.183 回答
1

鉴于这种情况很少发生并且实际处理时间（由跨度长度表示）很短，我怀疑某种 App Engine 缩放操作正在后台发生。例如，减速可能是由于向您的应用程序添加了新实例。您可以通过查看 App Engine 仪表板上的活动图或使用 AppStats 进一步深入了解这一点（请参阅此SO 帖子）。

在跟踪时间线视图中显示 App Engine 事件是我们一段时间以来一直想做的事情，因为它会显着缩短此类情况的分析过程。

于 2016-08-24T20:53:42.470 回答