Changes between Version 8 and Version 9 of ProfilingDjango

Timestamp:

Feb 11, 2010, 1:51:41 AM (15 years ago)

Author:

jdub

Comment:

--

ProfilingDjango

@@ -1 +1 @@
 = Profiling Django =
 
-[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.
+== Profiling Specific Code ==
 
-[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].
+Python 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.
+
+I wrap views and other callables I want to examine in a decorator like this one:
+
+{{{
+import hotshot
+import os
+import time
+
+PROFILE_LOG_BASE = "/tmp"
+import settings
+
+
+def profile(log_file):
+    """Profile some callable.
+
+    This decorator uses the hotshot profiler to profile some callable (like
+    a view function or method) and dumps the profile data somewhere sensible
+    for later processing and examination.
+
+    It takes one argument, the profile log name. If it's a relative path, it
+    places it under the PROFILE_LOG_BASE. It also inserts a time stamp into the 
+    file name, such that 'my_view.prof' become 'my_view-20100211T170321.prof', 
+    where the time stamp is in UTC. This makes it easy to run and compare 
+    multiple trials.     
+    """
+
+    if not os.path.isabs(log_file):
+        log_file = os.path.join(PROFILE_LOG_BASE, log_file)
+
+    def _outer(f):
+        def _inner(*args, **kwargs):
+            # Add a timestamp to the profile output when the callable
+            # is actually called.
+            (base, ext) = os.path.splitext(log_file)
+            base = base + "-" + time.strftime("%Y%m%dT%H%M%S", time.gmtime())
+            final_log_file = base + ext
+
+            prof = hotshot.Profile(final_log_file)
+            try:
+                ret = prof.runcall(f, *args, **kwargs)
+            finally:
+                prof.close()
+            return ret
+
+        return _inner
+    return _outer
+}}}
+
+Set a base path for storing profiling logs in your `settings.py` using `PROFILE_LOG_BASE`, then use it like this:
+
+{{{
+@profile("my_view.prof")
+def myview(request):
+...
+}}}
+
+This 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.
+
+To actually examine the results, you'll need to use the `hotshot.stats` module. A simple script like this:
+
+{{{
+#!/usr/bin/python
+
+import hotshot.stats
+import sys
+
+stats = hotshot.stats.load(sys.argv[1])
+#stats.strip_dirs()
+stats.sort_stats('time', 'calls')
+stats.print_stats(20)
+}}}
+
+(`stats.strip_dirs()` results in a more compact output, but I prefer to know which {{{__init__.py}}} I'm dealing with.)
+
+Here's some output from a profile of an authentication module I was having trouble with:
+{{{
+         7986 function calls (7850 primitive calls) in 1.725 CPU seconds
+
+   Ordered by: internal time, call count
+   List reduced from 392 to 20 due to restriction <20>
+
+   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
+        2    1.570    0.785    1.570    0.785 /usr/local/lib/python2.5/django/db/backends/__init__.py:36(_commit)
+       15    0.043    0.003    0.043    0.003 /usr/local/lib/python2.5/linecache.py:68(updatecache)
+        1    0.020    0.020    0.027    0.027 /usr/local/lib/python2.5/django/contrib/auth/models.py:1(<module>)
+       12    0.014    0.001    0.030    0.002 /usr/local/lib/python2.5/django/utils/importlib.py:18(import_module)
+     1013    0.010    0.000    0.010    0.000 /usr/local/lib/python2.5/posixpath.py:56(join)
+}}}
+
+This 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. 
+
+You 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`.
+
+You can also examine the results with [http://kcachegrind.sourceforge.net/ KCacheGrind] by using it's `hotshot2calltree` conversion scripts. 
+
+== Profiling Everything ==
+
+=== Middleware ===
 
 [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.
 
-[http://code.google.com/p/django-profiling/ django-profiling] seems to be another variant of the profiling middleware.
+Unfortunately, these are both items on Django Snippets, so you should treat them as being untested abandonware, or, more charitably, example code. 
 
-----
+[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.
 
-{{{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.
+=== Profiling at the server ===
 
+==== mod_python ====
+{{{django.core.handlers.profiler-hotshot}}} provides profiling support for Django when using `mod_python`. TODO: describe how to use this.
 
-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:
+==== Development Server ====
+[http://code.google.com/p/django-command-extensions/ django-command-extensions] provides a `runprofileserver` command for running the development server using the hotshot library.
 
-{{{
->>> import hotshot.stats
->>> stats = hotshot.stats.load("stones.prof")
->>> stats.strip_dirs()
->>> stats.sort_stats('time', 'calls')
->>> stats.print_stats(20)
-}}}
+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 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
+==== WSGI ====
 
-== Using WSGI to profile ==
-
-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:
+An 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`:
 
 {{{
@@ -61 +154 @@
 }}}
 
+== Other Approaches ==
+
+[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].
+