我在标准 Google 应用程序引擎日志中看到一些神秘的时间字段，这让我很好奇：
2011-05-09 21:56:00.577 /whatever 200 211ms 775cpu_ms 589api_cpu_ms
0.1.0.1 - - [09/May/2011:21:56:00 -0700] "GET /whatever HTTP/1.1"
200 34 - "AppEngine-Google; (+http://code.google.com/appengine)"
"****.appspot.com" ms=212 cpu_ms=776 api_cpu_ms=589 cpm_usd=0.021713
queue_name=__cron task_name=dc4d411120bc75ea8bbea773d23eaecc
特别是：ms、cpu_ms、api_cpu_ms，每个字段它们两次的值略有不同。
此外，当我自己使用下面的 GET 请求的简单结构记录计时信息时，它打印的值稍低。在本例中，特别是 182 毫秒，与官方的 775 毫秒不同。
protected void doGet(HttpServletRequest req, HttpServletResponse resp) {
long t0 = System.currentTimeMillis();
//Do the stuff
long t1 = System.currentTimeMillis();
log.info("Completed in " + (t1-t0) + " msecs.\n");
}
所以，我的问题是：为什么我的测量时间结果和 cpu_ms 值之间存在差异以及如何降低它？ GAE 日志字段中时间值的确切含义是什么？
我想优化我的代码，并且根据上述事实我意识到，大多数时间（近 600 毫秒！）并没有直接花费在 doGet 请求期间。 （我使用 JPA、URLFetch，这是一个 cron 任务。）
I see some enigmatic time fields in the standard Google app-engine logs which make me curious:
2011-05-09 21:56:00.577 /whatever 200 211ms 775cpu_ms 589api_cpu_ms
0.1.0.1 - - [09/May/2011:21:56:00 -0700] "GET /whatever HTTP/1.1"
200 34 - "AppEngine-Google; (+http://code.google.com/appengine)"
"****.appspot.com" ms=212 cpu_ms=776 api_cpu_ms=589 cpm_usd=0.021713
queue_name=__cron task_name=dc4d411120bc75ea8bbea773d23eaecc
Particularly: ms, cpu_ms, api_cpu_ms, each of them two times with slightly different values.
Additionally, when I log timing information myself with a simple structure below for the GET request, it prints a somewhat lower value. In this case, particulary 182 msecs, against the official 775.
protected void doGet(HttpServletRequest req, HttpServletResponse resp) {
long t0 = System.currentTimeMillis();
//Do the stuff
long t1 = System.currentTimeMillis();
log.info("Completed in " + (t1-t0) + " msecs.\n");
}
So, my questions are: Why the difference between my measured time result and the cpu_ms value and how could I lower it? What are the exact meaning of time values in GAE log fields?
I want to optimize my code and I realized based on the aforementioned facts, that most time (nearly 600 msecs!) doesn't spent directly during doGet request. (I use JPA, URLFetch and this is a cron task.)
发布评论
评论（1）
211ms：这是响应时间，请求该页面的用户会感知到该时间。您将尝试减少它，以提高网站的速度。
775cpu_ms：根据 App Engine 文档，“CPU 时间以“秒”为单位报告，相当于 1.2 GHz Intel x86 处理器在该时间内可以执行的 CPU 周期数。实际 CPU 周期数根据 App Engine 内部条件的不同，花费的时间差异很大，因此使用该处理器作为参考测量来调整此数字以用于报告目的。”
然后，没有“真实”时间是正常的：它应该与您使用
System.currentTimeMillis()测量的值，因为它已经过调整。相反，您应该使用 Quota API 来监控 CPU 使用情况：请参阅文档 此处。 CPU 时间是计费的（免费配额为每天 6.5 个 CPU 小时，您可以支付更多 CPU 时间）。然后，你会尝试减少它，以减少支付。589api_cpu_ms：这是 API 使用（数据存储、用户 API 等）所花费的调整后的 CPU 时间
211ms: It's the response's time, as it will be perceived by the user who requested the page. You will try to decrease it, in order to improve the speed of your website.
775cpu_ms: According to the App Engine documentation, "CPU time is reported in "seconds," which is equivalent to the number of CPU cycles that can be performed by a 1.2 GHz Intel x86 processor in that amount of time. The actual number of CPU cycles spent varies greatly depending on conditions internal to App Engine, so this number is adjusted for reporting purposes using this processor as a reference measurement."
Then, it's normal not to have the "real" time: it should be different from what you measured with
System.currentTimeMillis()because it's adjusted. Instead, you should use the Quota API to monitor the CPU usage: see documentation here. CPU time is billable (the free quota is 6.5 CPU-hours per day, and you can pay for more CPU time). Then, you will try to decrease it, in order to pay less.589api_cpu_ms: It's the adjuested CPU time spent by the API usage (Datastore, User API, etc.)