GAE/J request log format breakdown

Question

Here is a sample of GAE Console log record:

http://i.stack.imgur.com/M2iJX.png for readable high res version.

I would like to provide a breakdown of the fileds, displayed both in the collpased (summary) view and the expended (detail) view. I will fill the fields I know their meaning and would appreciate assistannce with dichipering the rest. This post will be updated once new information is available.

Thank you,
Maxim.

---

Open issues:

• How to read timestamp? [...-prod/0-0-39.346862139187007139]
• Why in summary it says request took 343ms but in details is says 344ms ?
• If request spend 123ms on cpu and 30ms on API calls where did the rest of the time go? Why the total request time is 343/344ms ?

Answer 1

Summary

• 12-14 : Date of the request. 12 is the month (December), 14 is the day of the month (Tuesday).
• 05:21AM : Time of the request, PST offset. 05 is the hour. 21 is the minute.
• 57.593 : Time of request, PST offset. 57 is the second. 593 is the millisecond.
• /match/... : HTTP request path
• 200 : HTTP return code. (200 = OK)
• 343ms : The total time (in milliseconds) it took to calculate and return the response to the user
• 123cpu_ms : The time (in milliseconds) the request spend on CPU calculation
• 30api_cpu_ms : The time (in milliseconds) the request spend on API calls (Datastore get and co...)
• 1kb : The size (in kilobytes) of the response that was sent to the user
• Mozilla/5.0 (X11; U; Linux x86_64; en-US) AppleWebKit/534.7 (KHTML, like Gecko) Chrome/7.0.517.44 Safari/534.7,gzip(gfe) : User Agent note that gzip(gfe) is added by AppEngine front end.

Details

• IP yellow masked out : The IP address of the client initiating the request
• HTTP Referrer : Note that it's empty on this request because it's a direct hit
• [14/Dec/2010:05:21:57 -0800] : Date, including timestamp offset specification.
• "GET /match/... HTTP/1.1" : The HTTP GET URI.
• 200 : HTTP return code. (200 = OK)
• 1036 : The size (in bytes) of the response that was sent to the user
• Mozilla/5.0 (X11; U; Linux x86_64; en-US) AppleWebKit/534.7 (KHTML, like Gecko) Chrome/7.0.517.44 Safari/534.7,gzip(gfe) : User Agent note that gzip(gfe) is added by AppEngine front end.
• ms=344 : The total time (in milliseconds) it took to calculate and return the response to the user
• cpu_ms=123 : The time (in milliseconds) the request spend on CPU calculation
• api_cpu_ms=30 : The time (in milliseconds) the request spend on API calls (Datastore get and co...)
• cpm_usd=0.003648 : The amount (in us $) that 1000 requests such as this one would cost. ref

log record

• 12-14 : Date of this specific application emitted log entry. 12 is the month (December), 14 is the day of the month (Tuesday).
• 05:21AM : Time of this specific application emitted log entry, PST offset.
• 57.833 : Time of request, PST offset. 57 is the second. 833 is the millisecond.
• [...-prod/0-0-39.346862139187007139] : The identifier of current version of the application that emitted this log message. Note: ...-prod is the application name. 0-0-39 is the deployed version name (app.yaml). .346862139187007139 is the time? (in what format?) when this version was deployed to appengine cloud.
• stdout : The channel to which the application emitted this log message. Can be either stdout or stderr.
• INFO ....Matcher - ... Id 208 matched. : Application level output. Can be done via either System.out.print or (as in this case) using a logging framework, logback

Answer 2

Isn't 57.593 seconds.milliseconds? And cpm_usd represents an estimate of what 1,000 requests similar to this request would cost in US dollars.