Cold app startup stats in case you're curious

[cz]

I added some timing code to see how expensive a cold app startup is.
This is a Django1.x app so YMMV.

The typical numbers are:

Zipimport of Django: 180ms
Appengine-django-helper monkeypatching: 430ms
Misc imports, app-specific patching, etc: 20ms
------------------------------------------------------------------------
Total app startup: 630ms

This is for startup only, not the time it takes to then process the
request, so this is a fixed expense. Also, this is real time not cpu
quota time which is much higher.

The biggest hog is the django-helper monkeypatcher. I'm eventually
going to try appengine-patch with the hope that it will be faster.

Additionally, on a cold startup my app processes a request in about
500ms, but on a warm app it only takes 10ms due to some aggressive
caching. I think that when all your app instances expire so does all
it's memcached data.

If anybody has done something similar and found different numbers
please post the results and let me know what I did wrong.


Here's the main.py I'm using in case you'd like to point out any
errors in my methodology:
----------------------------------------

from time import clock
t_main_start = clock()

# Standard Python imports.
import os
import sys
import logging
import settings

logging.getLogger().setLevel(settings.LOGGING_LEVEL)

# Fix (hack) for missing unlink
if os.name == 'nt':
os.unlink = lambda: None

# TODO (after gathering stats): remove this since appengine_django
does it for us
# Import Django 1.x from a zipfile and get rid of v.96.
t_zip_start = clock()
django_zip_path = os.path.abspath('django.zip')
if django_zip_path not in sys.path:
sys.path.insert(0, django_zip_path)
for k in [k for k in sys.modules if k.startswith('django')]:
del sys.modules[k]
# TODO (after gathering stats): remove this line
from django import template # provoke django zipimport
t_zip = (clock() - t_zip_start) * 1000

# Install appengine_django. Patches Django 1.x for use with GAE
t_patch_start = clock()
from appengine_django import InstallAppengineHelperForDjango
InstallAppengineHelperForDjango()
t_patch = (clock() - t_patch_start) * 1000

# Patch the appengine_django patch to fix User object creation
# Remove this when switching to appengine-patch
from monkeypatch import patch
patch()

# Google App Engine imports.
from google.appengine.ext.webapp import util

# Import the part of Django that we use here.
import django.core.handlers.wsgi

t_main = (clock() - t_main_start) * 1000
logging.info('[TIME] main.py startup: %.1fms (zipimport: %.1fms,
appengine-django: %.1fms)' % (t_main,t_zip,t_patch))

def real_main():
t_request_start = clock()
# Create a Django application for WSGI.
application = django.core.handlers.wsgi.WSGIHandler()

# Run the WSGI CGI handler with that application.
util.run_wsgi_app(application)
t_request = (clock() - t_request_start) * 1000
logging.info('[TIME] request: %.1fms' % t_request)

def profile_main():
# Rename this to main() for profiling
import cProfile, pstats
prof = cProfile.Profile()
prof = prof.runctx("real_main()", globals(), locals())
print "<pre>"
stats = pstats.Stats(prof)
stats.sort_stats("time") # Or cumulative
stats.print_stats(80) # 80 = how many to print
# The rest is optional.
#stats.print_callees()
#stats.print_callers()
print "</pre>"

main = real_main

if __name__ == '__main__':
main()

[Nash-t]

very useful. Any thoughts on how this compares to the start-up of
regular GAE (0.96)?

[Robert]

Useful stuff, thanks!

Just yesterday I was looking into this same issue. I was wondering if
plain 0.96 Django use (without appengine helper or patch) would be
significantly faster, and your post really makes me want to try that.
I changed the handling of a single url in my app to be a "plain" GAE
(webapp.WSGIApplication) handler. This URL was for a cron-triggered
task that runs every minute. In the absence of other traffic this
resulted in a cold start every minute and this processing this trivial
request now only uses approx. 200 ms CPU quota. When it was part of
the main Django app, it would take over 2000 ms CPU quota.

BTW I'm fairly convinced that memcached data doesn't get flushed out.

[cz]

Django is pretty resource intensive what with all the middleware and
template processing so it makes sense that a more minimal app would be
much faster. As for using .96 my guess is that you'd save ~180ms by
skipping zipimport and a fair bit more by not having to compile all
the imports (assuming the default GAE libraries are *.pyc). I'm still
kind of a Python newbie (old Java/C++ prgmr) so this explanation might
be completely wrong. Please post your results if you try it out!
You're probably right about memcache, I was trying to figure out where
all that extra response time (not startup time) came from on a cold
start (500ms cold vs 10ms warm). Maybe it's just the Python
interpreter having to compile all the response processing code.
My app serves uploaded images and other longer term datastore
blobjects, and using a Django view to serve them up is super slow when
cold. I'm thinking of using the lighter weight webapp framework just
to serve this kind of content. I didn't want to use more than one
framework for the app, but it's probably worth it in this case. For
lower traffic apps anyway.
regards,
- Claude

[Brandon Thomson]

My apps all use webkit/0.96 django templates. Cold start times are
<10ms for handlers that don't use templates and closer to 50ms for
handlers that do.