首页 文章

Google App Engine - Cloud 控制台Stackdriver跟踪详细信息

提问于
浏览
3

我正在尝试更好地了解Google的 Cloud 控制台堆栈驱动程序跟踪显示调用详细信息的方式,并调试我的应用程序的一些性能问题 . 大多数请求都与memcache set / get操作有很大关系,我在这里遇到了一些问题,但我不明白为什么调用之间存在很长时间的差距 . 我上传了2个截图 .

call @1025ms

call @5235ms

所以,正如你所看到的,@ 1025ms的呼叫耗时2ms,但它和urlfetch呼叫@ 5235ms之间的距离超过4秒 .

首先,我的代码在那时并不密集(并且完整请求显示大约9000ms的未跟踪时间),第二,运行相同代码的大多数类似请求没有这些间隙(即,重复请求不会有相同的行为) . 但我也在其他请求中也看到了这个问题,我无法重现它们 .

请指教!

EDIT:

我已经从appstats上传了另一个截图 . 这是一个“正常”请求,通常需要几百毫秒才能运行(最多1秒),也需要在localhost(开发)中 . 我无法找到任何进一步调试的东西 . 我觉得我遗漏了一些简单的东西,基础层面的东西,关于app引擎的DO和DO NOTs .

appstats

2 回答

  • 1

    我知道这些差距的以下常见原因(“未跟踪时间”):

    • 在这些间隙期间,请求实际上是CPU绑定的 .

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

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

    该指标也可在 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 ,以检查您的请求是否因此而缓慢 . 考虑Configuring Warmup Requests to Improve Performance .

    Protip,如果您想在日志查看器中将调查过滤器集中在这样的 loading requests ,请应用此高级过滤器:

    protoPayload.megaCycles > 10000 and protoPayload.wasLoadingRequest=false
    
    • 应用程序代码的某些部分因过度使用反射而大幅减慢速度 . 这特定于App Engine标准环境,其中安全管理器限制反射的使用 . 只有缓解才能减少反射 . 请注意,App Engine服务基础架构不断发展,因此这个提示有可能很快就会过时 .

    如果问题在dev appserver中可以在本地重现,则可以使用分析器(或者可能只是jstack)来缩小范围 . 在其他一些情况下,我确实必须逐步将应用程序代码二等分,添加更多日志语句,重新部署等,直到识别出有问题的代码 .

    • App Engine标准环境中的Stackdriver Trace实际上没有开箱即用的后端调用 . 到目前为止我唯一知道的例子是Cloud SQL . 考虑使用Google Cloud Trace for JDBC来跟踪与Cloud SQL的交互 .

    • 该应用程序是多线程的(太棒了!)并且遇到了一些自我造成的同步问题 . 我在野外看过的例子:

    • 特定于应用程序的同步强制对存储后端的所有请求进行序列化(对于给定的App Engine实例) . 除了那些神秘的空隙之外,没有任何东西在痕迹中突出......

    • 应用程序使用数据库连接池 . 并行请求数超过了容量池(对于给定的App Engine实例),某些请求必须等到连接可用 . 这是前一项的更复杂的变体 .

  • 2

    鉴于这种情况很少发生并且实际处理时间(由 Span 长度表示)很短,我怀疑是某种App Engine缩放操作正在后台发生 . 例如,减速可能是由添加到应用程序的新实例引起的 . 您可以通过查看App Engine仪表板上的活动图或使用AppStats(参见this SO帖子)进一步深入研究 .

    在跟踪时间线视图中显示App Engine事件是我们一直希望做的事情,因为它会大大缩短这种情况下的分析过程 .

相关问题