Code

Changes between Version 8 and Version 9 of ProfilingDjango


Ignore:
Timestamp:
02/10/10 23:51:41 (4 years ago)
Author:
jdub
Comment:

--

Legend:

Unmodified
Added
Removed
Modified
  • ProfilingDjango

    v8 v9  
    11= Profiling Django = 
    22 
    3 [http://code.google.com/p/django-command-extensions/ django-command-extensions] provides a `runprofileserver` command for running the development server with hotshot/profiling tools enabled. It has the ability to export [http://kcachegrind.sourceforge.net/ KCacheGrind] compatible profile files. 
     3== Profiling Specific Code == 
    44 
    5 [http://www.mysoftparade.com/blog/django-profile-sql-performance/ django-profile.py] is a script that can be used to profile any Django-powered web-site and find how many SQL-queries are used per page, how heavy html-pages are, etc.  See also [http://www.djangosnippets.org/snippets/461/ django snippet 461]. 
     5Python has several profiling modules, the least worst of which is the apparently unmaintained [http://docs.python.org/library/hotshot.html hotshot]. It's better than the Profiler module for our purposes as it has simple 'start' and 'stop' methods, as well as a method that takes a callable and it's arguments. 
     6 
     7I wrap views and other callables I want to examine in a decorator like this one: 
     8 
     9{{{ 
     10import hotshot 
     11import os 
     12import time 
     13 
     14PROFILE_LOG_BASE = "/tmp" 
     15import settings 
     16 
     17 
     18def profile(log_file): 
     19    """Profile some callable. 
     20 
     21    This decorator uses the hotshot profiler to profile some callable (like 
     22    a view function or method) and dumps the profile data somewhere sensible 
     23    for later processing and examination. 
     24 
     25    It takes one argument, the profile log name. If it's a relative path, it 
     26    places it under the PROFILE_LOG_BASE. It also inserts a time stamp into the  
     27    file name, such that 'my_view.prof' become 'my_view-20100211T170321.prof',  
     28    where the time stamp is in UTC. This makes it easy to run and compare  
     29    multiple trials.      
     30    """ 
     31 
     32    if not os.path.isabs(log_file): 
     33        log_file = os.path.join(PROFILE_LOG_BASE, log_file) 
     34 
     35    def _outer(f): 
     36        def _inner(*args, **kwargs): 
     37            # Add a timestamp to the profile output when the callable 
     38            # is actually called. 
     39            (base, ext) = os.path.splitext(log_file) 
     40            base = base + "-" + time.strftime("%Y%m%dT%H%M%S", time.gmtime()) 
     41            final_log_file = base + ext 
     42 
     43            prof = hotshot.Profile(final_log_file) 
     44            try: 
     45                ret = prof.runcall(f, *args, **kwargs) 
     46            finally: 
     47                prof.close() 
     48            return ret 
     49 
     50        return _inner 
     51    return _outer 
     52}}} 
     53 
     54Set a base path for storing profiling logs in your `settings.py` using `PROFILE_LOG_BASE`, then use it like this: 
     55 
     56{{{ 
     57@profile("my_view.prof") 
     58def myview(request): 
     59... 
     60}}} 
     61 
     62This will produces files of the form `/path/to/logs/my_view-20100211T170321.prof`, so you can test your view under various input conditions and compare the results. 
     63 
     64To actually examine the results, you'll need to use the `hotshot.stats` module. A simple script like this: 
     65 
     66{{{ 
     67#!/usr/bin/python 
     68 
     69import hotshot.stats 
     70import sys 
     71 
     72stats = hotshot.stats.load(sys.argv[1]) 
     73#stats.strip_dirs() 
     74stats.sort_stats('time', 'calls') 
     75stats.print_stats(20) 
     76}}} 
     77 
     78(`stats.strip_dirs()` results in a more compact output, but I prefer to know which {{{__init__.py}}} I'm dealing with.) 
     79 
     80Here's some output from a profile of an authentication module I was having trouble with: 
     81{{{ 
     82         7986 function calls (7850 primitive calls) in 1.725 CPU seconds 
     83 
     84   Ordered by: internal time, call count 
     85   List reduced from 392 to 20 due to restriction <20> 
     86 
     87   ncalls  tottime  percall  cumtime  percall filename:lineno(function) 
     88        2    1.570    0.785    1.570    0.785 /usr/local/lib/python2.5/django/db/backends/__init__.py:36(_commit) 
     89       15    0.043    0.003    0.043    0.003 /usr/local/lib/python2.5/linecache.py:68(updatecache) 
     90        1    0.020    0.020    0.027    0.027 /usr/local/lib/python2.5/django/contrib/auth/models.py:1(<module>) 
     91       12    0.014    0.001    0.030    0.002 /usr/local/lib/python2.5/django/utils/importlib.py:18(import_module) 
     92     1013    0.010    0.000    0.010    0.000 /usr/local/lib/python2.5/posixpath.py:56(join) 
     93}}} 
     94 
     95This shows that the culprit is the database commit code; while my queries where fast, actually committing the results to a SQLite database is causing me grief.  
     96 
     97You can use [http://code.djangoproject.com/browser/django/trunk/django/bin/profiling/gather_profile_stats.py gather_profile_stats.py] in the Django distribution to aggregate the generated profile logs and open them with `pstats.Stats`. 
     98 
     99You can also examine the results with [http://kcachegrind.sourceforge.net/ KCacheGrind] by using it's `hotshot2calltree` conversion scripts.  
     100 
     101== Profiling Everything == 
     102 
     103=== Middleware === 
    6104 
    7105[http://www.djangosnippets.org/snippets/186/ Profiling Middleware] and [http://www.djangosnippets.org/snippets/605/ Extended Profiling Middleware] print profile results for method, additionally groups results by files and by modules. Add the "&prof=" query parameter and you'll see the profiling results in your browser. 
    8106 
    9 [http://code.google.com/p/django-profiling/ django-profiling] seems to be another variant of the profiling middleware. 
     107Unfortunately, these are both items on Django Snippets, so you should treat them as being untested abandonware, or, more charitably, example code.  
    10108 
    11 ---- 
     109[http://code.google.com/p/django-profiling/ django-profiling] seems to be another variant of the profiling middleware, which declares itself superseded by [http://code.google.com/p/django-logging/wiki/Overview django-logging], which declares itself unmaintained. 
    12110 
    13 {{{django.core.handlers.profiler-hotshot}}} provides profiling support for Django when using mod_python. Hotshot generates logs that can be also used by aplication like kcachegrind. Read [http://www.rkblog.rk.edu.pl/w/p/django-profiling-hotshot-and-kcachegrind/ Django profiling with hotshot and kcachegrind] for more details. 
     111=== Profiling at the server === 
    14112 
     113==== mod_python ==== 
     114{{{django.core.handlers.profiler-hotshot}}} provides profiling support for Django when using `mod_python`. TODO: describe how to use this. 
    15115 
    16 Here's a similar solution for the internal development webserver. Apply the included patch to {{{django/core/management.py}}} and start Django with {{{manage.py runserver}}}. Each request will create a {{{.prof}}} file in your {{{/tmp}}} directory. You can then open a Python shell and print the statistics: 
     116==== Development Server ==== 
     117[http://code.google.com/p/django-command-extensions/ django-command-extensions] provides a `runprofileserver` command for running the development server using the hotshot library. 
    17118 
    18 {{{ 
    19 >>> import hotshot.stats 
    20 >>> stats = hotshot.stats.load("stones.prof") 
    21 >>> stats.strip_dirs() 
    22 >>> stats.sort_stats('time', 'calls') 
    23 >>> stats.print_stats(20) 
    24 }}} 
     119A similar solution for the internal development webserver: apply the included patch to {{{django/core/management.py}}} and start Django with {{{manage.py runserver}}}. Each request will create a {{{.prof}}} file in your {{{/tmp}}} directory.  
    25120 
    26 You can also use [http://code.djangoproject.com/browser/django/trunk/django/bin/profiling/gather_profile_stats.py gather_profile_stats.py] in the Django distribution to aggregate the generated profilings and open them with pstats.Stats 
     121==== WSGI ==== 
    27122 
    28 == Using WSGI to profile == 
    29  
    30 An alternative approach is to run django from a boring WSGI server and profile that. For example using wsgiref you can create a really simple WSGI server for running django: 
     123An alternative approach to using the built in development server is to run Django from a trivial WSGI server and profile that. For example, using `wsgiref`: 
    31124 
    32125{{{ 
     
    61154}}} 
    62155 
     156== Other Approaches == 
     157 
     158[http://www.mysoftparade.com/blog/django-profile-sql-performance/ django-profile.py] is a script that can be used to profile any Django-powered web-site and find how many SQL-queries are used per page, how heavy html-pages are, etc.  See also [http://www.djangosnippets.org/snippets/461/ django snippet 461]. 
     159