How do I profile `paster serve`'s startup time?

Question

Python's paster serve app.ini is taking longer than I would like to be ready for the first request.

I know how to profile requests with middleware, but how do I profile the initialization time? I would like it to not fork a thread pool and quit as soon as it is ready to serve so the time after it's ready doesn't show up in the profile.

Answer 1

In general your methodology could be to do timing blocks around the sections of code and then issue logging statements. As far as the shutdown after init, I'm not familiar with the specifics of what you're using.

Edit: I've used this middleware to help me find performance sinkholes. It's currently a werkzeug middleware, you may be able to adapt it for you usage. Hope it helps

import re
re_profile = re.compile(ur'(^|&|\?)prof($|=|&)')
class ProfilerMiddleware(BaseProcessor):
    def process_runner(self, runner, environ):
        self.profiler = None
        if (environ['REMOTE_ADDR'] in settings_static.internal_ips or settings_static.local_server) and re_profile.match(environ['QUERY_STRING']):
            self.profiler = cProfile.Profile()
            def wrap(*args, **kwargs):
                return self.profiler.runcall(runner, *args, **kwargs)
            return wrap

    def process_response(self, request, response):
        if self.profiler:
            self.profiler.create_stats()
            out = StringIO.StringIO()
            old_stdout, sys.stdout = sys.stdout, out
            #from dozer.profile import buildtree, write_dot_graph
            #write_dot_graph(self.profiler.getstats(), buildtree(self.profiler.getstats()), "/tmp/output.gv")
            self.profiler.print_stats(1)
            sys.stdout = old_stdout
            response.response = [u'<pre>%s</pre>' % to_unicode(out.getvalue())]
            response.content_type = 'text/html'

Answer 2

Even if you'd profile it - I doubt you get to much hints to optimize.

We use Paster inside a mod_wsgi setup, and to mitigate the startup time so that the user doesn't suffer from it, and make sure that e.g. toscawidgets are set up properly, we do this:

app = paste.fixture.TestApp(application)
# TODO-dir: FIXME, must go away!
try:
    app.get("/")
except:
    pass

Here application is of course the initialized/loaded paster app.

Answer 3

I almost always use paster serve --reload ... during development. That command executes itself as a subprocess (it executes its own script using the subprocess module, not fork()).

The subprocess polls for source code changes, quits when it detects a change, and gets restarted by the parent paster serve --reload.

That's to say if you're going to profile paster serve itself, omit the --reload argument. Profiling individual requests with middleware should work fine either way.

My particular problem was that pkg_resources takes an amount of time proportional to all installed packages when it is first invoked. I solved it by rebuilding my virtualenv without unnecessary packages.