为什么Google App Engine日志中的请求时间与Appstats中的请求时间不同？

我在Google App Engine的基于Java的HDR应用程序上运行Appstats。现在我对实际的App Engine请求日志和Appstats日志之间的时间差异感到困惑。这段时间似乎有相当的漂移。解释我的意思是我带了一些截图。他们都来自同一个请求。为什么Google App Engine日志中的请求时间与Appstats中的请求时间不同？

这一个是从App Engine的请求日志：

而这一次是从将Appstats相同的请求：

下面是测量一个列表我能够提取：

Log Timestamp   10:10:33.156 
Log "Total"     147ms 
Log "ms"      147ms 
Log "cpu_ms"     86ms 

Appstats Timestamp  10:10:33.072 
Appstats "Grand Total"   39ms 
Appstats "real"     39ms 
Appstats "RPC Total"   20ms 
Appstats "api"     0ms 
Appstats "overhead"    0ms

正如你可以看到，有两个在请求时间戳和运行时相当的差异：

Difference Log/AS Timestamps 84ms 
Difference Log/AS Total  108ms (377%)

顺便说一句：虽然请求时间戳是不一样的它仍然是相同的请求：我跟着链接将Appstats发布到请求日志中，并在未使用的测试应用程序上执行此测试，以便确保链接正确。

为什么Appstats告诉我我的请求需要39ms，而GAE请求日志告诉我请求的时间长了3.8x（147ms）？为什么相同的请求有两个不同的时间戳？

Thanksalot！

来源

2014-02-10 Holger

将appstats挂钩到代码中，在您的代码（appstats）被调用之前以及在appstats退出之后还会有一段时间。记住appengine不会流到客户端，但所有的输出都是到某种类型的缓冲区，然后传递给appengine基础架构进行传送。

请求的时间表将会像

开始的请求（开始你在日志中看到的时间）将Appstats覆盖的代码
将Appstats年底覆盖的代码
最终的
启动回应发送（总持续时间）

这将是有趣的，看看多少1和4将平均，和th可能取决于运行时间。

哦，将Appstats本身会产生一定的开销，这会不会被测量的Appstats，包括启动，并在结束清理，这在1和2

来源

2014-02-10 11:27:13

您好添贡献的时候了！非常感谢您的回复。我明白，在Appstats可以启动前，每个请求都会有一些“封闭”开销。有趣的是，Appstats时间戳在请求日志时间戳之前，这表明日志时间戳不是请求的开始？ – Holger

或者，日志记录系统开始请求时间不是来自同一时钟，而是来自前端基础设施 - 只是一个猜测。 –

实际上，如果您考虑它，日志条目来自日志服务，时间戳将来自日志服务。日志服务时钟可能与您的实例时钟不同（实例时钟可能会彼此稍微偏离）。要测试此理论，请记录您创建的时间戳，并查看它是否与日志条目时间戳匹配。 –

为什么Google App Engine日志中的请求时间与Appstats中的请求时间不同？

回答

相关问题