Demystifying the App Engine request logs
Posted by Nick Johnson | Filed under python, app-engine, java, logs
People often ask about the App Engine request logs shown in the admin console: What do all the fields mean? How should they be interpreted? They're actually fairly easy to read once you know the format, so here's a quick-reference to help.
The basic format is based on the Apache combined log format, which is so widely used even outside Apache that it's become a de-facto standard of sorts for webserver request logs. In addition to that, App Engine adds a number of extra fields logging additional, App Engine specific stats. Suppose you're examining the following log entry:
107.10.42.191 - foobiz [10/May/2011:17:26:28 -0700] "GET /page.html HTTP/1.1" 500 2297 "http://www.example.com/home.html" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; en-us) AppleWebKit/533.19.4 (KHTML, like Gecko) Version/5.0.3 Safari/533.19.4,gzip(gfe),gzip(gfe),gzip(gfe)" "www.example.com" ms=364 cpu_ms=23 api_cpu_ms=0 cpm_usd=0.001059
Here's what the fields mean, in order:
- Client's IP address (107.10.42.191)
- The RFC1413 identity of the client (in practice, always '-')
- The userid determined by HTTP authentication ('foobiz')
- The timestamp of the request ('[10/May/2011:17:26:28 -0700]')
- The first line of the request, containing request method, path, and HTTP protocol version ("GET /page.html HTTP/1.1")
- The status code returned by the server (500)
- The size in bytes of the response (2297)
- The referer path ("http://www.example.com/home.html")
- The user-agent ("Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; en-us) AppleWebKit/533.19.4 (KHTML, like Gecko) Version/5.0.3 Safari/533.19.4,gzip(gfe),gzip(gfe),gzip(gfe)")
- The hostname
- The wallclock milliseconds required to fulfill the request
- The CPU milliseconds required to fulfill the request
- The CPU milliseconds spent by API calls
- An estimate of the cost of 1000 requests like this, in USD.
The first 9 fields form the apache Combined log format; the remainder are App Engine specific. The hostname field was added because it's frequently useful in environments where your app may be accessed by multiple different hostnames, and behave differently for each. The remainder of the fields deal with various timing statistics, and bear additional explanation.
There are several timing statistics that matter to an App Engine request. The first and arguably most important is the wallclock time. This is the actual time (hence 'wallclock' time) taken to return a response to the user, not including the time it took for the user to send their request or the time it takes to send the response back - that is, just the time spent processing by your app. Keeping this low is important for two reasons: firstly, because the faster your app is, the better the user-experience and second, because App Engine - at least until the new pricing model comes into effect - will only auto-scale your app if its average wallclock response time is below 1000 ms.
The second time recorded is CPU milliseconds. These, nominally, refer to the number of milliseconds spent by a CPU - the one in the app server your app was served by - while executing your code. This figure is based on a nominal 1.2 GHz Intel x86 processor, so it's possible for this figure to be higher than the wallclock seconds if the processor your app was executed on is faster than that.
The third time is the "API CPU ms", the number of milliseconds of CPU time spent executing API calls, such as requests to the datastore or memcache. This, again, can be higher than the wallclock milliseconds, and for API calls frequently are, as one API call can be processed by many computers - for instance, when doing a batch put to the datastore. CPU milliseconds and API CPU milliseconds are combined and billed identically, but they're broken out in the logs to make it easier for you to see how much CPU time is spent directly by your app, and how much is spent by other APIs you call. Appstats is essential for determining where the time is going and reducing it, of course.
Finally is the CPM field. This field estimates the cost of 1000 requests like the logged one, by taking the cost of the resources this request used - CPU time amongst others - and multiplying it by 1000. This can be very useful for figuring out exactly how cost-effective your app is by providing a real-world figure to compare against.
Hopefully the App Engine logs are no longer such a mystery now. Still have questions? Ask them in the comments!
Previous Post Next Post