Profiling QP applications
Earlier this month Chris McDonough posted profile summaries of four Python web frameworks: repoze.bfg, Django, Pylons, and Grok.
The framework I use, QP, supports WSGI but doesn't depend on it, which is neither good nor bad but perhaps as a result I'm a little less aware of the WSGI ecosystem than I should be so I am trying to find time to look at various middleware and application components.
Following up on Chris's post I took the profiling middleware from repoze.profile for a spin to satisfy the latent WSGI curiosity percolating here under the covers. Using paste.httpserver failed for reasons I cannot at this time recall, yet driving the middleware and QP via the basic WSGI reference server was successful. I suppose I'll track that down when I have a real need.
Compared to the list of results in "What's Your Web Framework Doing (2)", QP fits in with the Django results, returning 57 lines of profiler output for a simple GET request from a hello, world application.
I should point out that you can profile any QP application from the included interactive console which provides access to the profiler, as well as to the Durus Python object database containing your application's objects:
$ qp -i hello
Profile, publisher, site
>>> p = Profile('/')
>>> p.stats.strip_dirs()
<pstats.Stats instance at 0x875e7ac>
>>> p.sort('time')
>>> p.format()
Wed Feb 18 18:08:33 2009 /tmp/tmpQJy4QF.profile
105 function calls in 0.007 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.004 0.004 0.006 0.006 <string>:1(<module>)
1 0.000 0.000 0.001 0.001 response.py:375(write)
1 0.000 0.000 0.000 0.000 :0(now)
5 0.000 0.000 0.001 0.000 response.py:320(generate_headers)
12 0.000 0.000 0.000 0.000 utils.py:44(as_bytes)
1 0.000 0.000 0.007 0.007 profile:0(hit, page = process())
17 0.000 0.000 0.000 0.000 :0(isinstance)
7 0.000 0.000 0.000 0.000 :0(write)
1 0.000 0.000 0.000 0.000 response.py:123(__init__)
7 0.000 0.000 0.000 0.000 :0(get)
1 0.000 0.000 0.003 0.003 profiler.py:50(process)
1 0.000 0.000 0.000 0.000 hit.py:32(init_response)
1 0.000 0.000 0.000 0.000 request.py:202(get_header)
1 0.000 0.000 0.000 0.000 request.py:105(__init__)
1 0.000 0.000 0.000 0.000 request.py:330(_parse_pref_header)
1 0.000 0.000 0.001 0.001 publish.py:94(process)
1 0.000 0.000 0.000 0.000 common.py:61(site_now)
1 0.000 0.000 0.000 0.000 :0(setprofile)
1 0.000 0.000 0.001 0.001 hit.py:25(__init__)
1 0.000 0.000 0.000 0.000 response.py:239(set_body)
1 0.000 0.000 0.000 0.000 request.py:306(get_encoding)
2 0.000 0.000 0.000 0.000 spec.py:737(get_specified_attribute)
1 0.000 0.000 0.000 0.000 rfc822.py:952(formatdate)
1 0.000 0.000 0.000 0.000 slash.py:19(process_hit)
1 0.000 0.000 0.000 0.000 request.py:373(parse_cookies)
2 0.000 0.000 0.000 0.000 response.py:361(generate_body_chunks)
1 0.000 0.000 0.000 0.000 response.py:156(set_status)
1 0.000 0.000 0.000 0.000 response.py:293(get_content_length)
1 0.000 0.000 0.000 0.000 common.py:23(get_publisher)
2 0.000 0.000 0.000 0.000 :0(items)
1 0.000 0.000 0.000 0.000 response.py:300(_gen_cookie_headers)
1 0.000 0.000 0.000 0.000 response.py:203(_compress_body)
2 0.000 0.000 0.000 0.000 :0(getattr)
2 0.000 0.000 0.000 0.000 response.py:144(set_compress)
2 0.000 0.000 0.000 0.000 tz.py:60(dst)
1 0.000 0.000 0.000 0.000 tz.py:40(now)
1 0.000 0.000 0.000 0.000 response.py:228(_encode_chunk)
1 0.000 0.000 0.000 0.000 :0(sub)
1 0.000 0.000 0.000 0.000 :0(time)
1 0.000 0.000 0.000 0.000 :0(finditer)
1 0.000 0.000 0.000 0.000 :0(replace)
1 0.000 0.000 0.000 0.000 :0(split)
1 0.000 0.000 0.000 0.000 :0(gmtime)
1 0.000 0.000 0.000 0.000 :0(match)
1 0.000 0.000 0.000 0.000 response.py:197(set_expires)
1 0.000 0.000 0.000 0.000 tz.py:54(utcoffset)
1 0.000 0.000 0.000 0.000 :0(upper)
1 0.000 0.000 0.000 0.000 :0(getvalue)
1 0.000 0.000 0.000 0.000 response.py:133(set_content_type)
1 0.000 0.000 0.000 0.000 response.py:153(get_buffered)
1 0.000 0.000 0.000 0.000 publish.py:484(get_time_zone)
1 0.000 0.000 0.000 0.000 response.py:150(set_buffered)
1 0.000 0.000 0.000 0.000 :0(len)
1 0.000 0.000 0.000 0.000 :0(lower)
1 0.000 0.000 0.000 0.000 :0(get_ident)
1 0.000 0.000 0.000 0.000 response.py:147(get_compress)
0 0.000 0.000 profile:0(profiler)
Nothing too surprising here nor is there much fluff. as_bytes (from the Durus package) gets called a number of times as from the same code base QP strives very hard to be a good Unicode citizen in both Python 2.x and 3.0+.