What are the exact meaning of time values in GAE l

Question

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.)

Answer 1

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.)