A few words on AppEngine logging (production)
Posted by David Chandler on March 5, 2010
The AppEngine production log viewer is the envy of most development and sysadmin teams I’ve ever worked with. It offers a a near real-time view into your application’s doings in a powerful Web-based interface. In addition to filtering on the standard JDK log levels, you can search a particular time period, filter any regex, and use labels to filter on
The request log shows every request, even images and CSS, so you can see why you need to turn on expiration headers for static files 🙂 RPC calls, cron jobs, task servlets–they’re all there. Furthermore, if your app is enabled for Google account authentication, every request is tagged with the Google user id. This is a poor man’s “fish tag” and is extremely helpful for real-time customer support with your mother-in-law (“Mom! You’re using IE 5!”).
If you’re using gwt-dispatch, you’ll notice that all requests to the dispatcher are logged alike (which also causes the Dashboard CPU meter to aggregate all requests to your dispatch servlet). With this in mind, I’m thinking of having the dispatch servlet log the Action class being invoked so I can put together something akin to a click trail. In addition, I wonder if there’s a way for the GWT dispatcher to append the action name as extra path info or query string? This way, the Dashboard might be able to break out which Actions are consuming the most CPU.
The only unpleasantness I’ve found is that AppEngine clutters up the logs with a bunch of harmless warnings about FinalizableReferenceQueue. You can easily get rid of them, however, by putting these lines to your WEB-INF/logging.properties:
# Hide harmless com.google.inject.internal.FinalizableReferenceQueue=WARNING com.google.inject.internal.FinalizableReferenceQueue$SystemLoader=WARNING com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue.level=WARNING
Actually, there is one more unpleasantness: the much-discussed cold start problem. If your app is not yet world-famous, AppEngine will cycle it out after only a few minutes of non-use. This issue has been beat to death on the forums, but suffice it to say it’s easy to spot: just look for the requests with CPU time in red that took 8 seconds after a period of inactivity. Lots of folks have said they’d be willing to stay “hot,” which seems like a good idea. For my part, I like the platform enough that I’m willing to bet Google will take this seriously.