CODEWITHSUNDEEP
djangoprofilinguwsgidjango-debug-toolbar
MikeAr
MikeAr

Reputation: 1051

Profiling Django application under uWSGI/Nginx

I am in the process of migrating a medium-sized Django 1.4.2 application to new infrastructure and trying to optimize system's performance on new, very powerful hardware. I am using django-debug-toolbar as well as hotshots-based profiling middleware to locate the bottlenecks and currently having a hard time understanding the difference in execution time values I get from different sources.

For instance, here are the timings I get if I make a single request to an URL in my application with is mapped to a rather simple view:

Nginx 1.2.5 - 0.409s:

10.10.1.101 151a6b897ee788499fd19d6531befaac [17/Dec/2012:23:43:53 -0800] 200 0.409 1633 "GET /product/150138/?prof HTTP/1.1" "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.97 Safari/537.11"

uWSGI 1.4.2 (64bit) - 387ms:

Mon Dec 17 23:27:50 2012 151a6b897ee788499fd19d6531befaac GET mysite.com/product/150138/?prof HTTP/1.1 200 387ms

Django-debug-toolbar - 112.452 msec:

Resource                 Value
User CPU time            84.005 msec
System CPU time          4.001 msec
Total CPU time           88.006 msec
Elapsed time             112.452 msec
Context switches         33 voluntary, 10 involuntary

SQL: 16.42 ms (8 queries)

Profiling middleware - 0.132 seconds:

113020 function calls (110410 primitive calls) in 0.132 seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    10232    0.046    0.000    0.046    0.000 /opt/myenv/lib/python2.7/posixpath.py:60(join)
    10187    0.032    0.000    0.040    0.000 /opt/myenv/lib/python2.7/posixpath.py:130(islink)
1396/1354    0.022    0.000    0.120    0.000 /opt/myenv/lib/python2.7/posixpath.py:355(realpath)
     2682    0.018    0.000    0.018    0.000 /opt/myenv/lib/python2.7/posixpath.py:312(normpath)
        8    0.016    0.002    0.016    0.002 /opt/myenv/lib/python2.7/site-packages/django/db/backends/postgresql_psycopg2/base.py:50(execute)
     1568    0.010    0.000    0.022    0.000 /usr/lib/python2.7/inspect.py:440(getsourcefile)
      214    0.009    0.000    0.138    0.001 /usr/lib/python2.7/inspect.py:472(getmodule)
       23    0.008    0.000    0.008    0.000 /opt/myenv/lib/python2.7/linecache.py:68(updatecache)
     1544    0.007    0.000    0.007    0.000 /opt/myenv/lib/python2.7/genericpath.py:15(exists)
        8    0.005    0.001    0.205    0.026 /opt/myenv/lib/python2.7/site-packages/debug_toolbar/utils/tracking/db.py:85(execute)
    10187    0.005    0.000    0.007    0.000 /opt/myenv/lib/python2.7/stat.py:55(S_ISLNK)
      458    0.005    0.000    0.008    0.000 /opt/myenv/lib/python2.7/site-packages/django/template/base.py:673(__init__)
        4    0.004    0.001    0.005    0.001 /opt/myenv/lib/python2.7/site-packages/memcache.py:965(_recv_value)
      395    0.004    0.000    0.011    0.000 /opt/myenv/lib/python2.7/site-packages/django/template/base.py:524(__init__)
     7243    0.004    0.000    0.004    0.000 /usr/lib/python2.7/inspect.py:51(ismodule)
     4078    0.003    0.000    0.003    0.000 /opt/myenv/lib/python2.7/posixpath.py:51(isabs)
   114/10    0.003    0.000    0.028    0.003 /opt/myenv/lib/python2.7/site-packages/django/template/base.py:234(parse)
     2504    0.003    0.000    0.021    0.000 /opt/myenv/lib/python2.7/posixpath.py:341(abspath)
      803    0.002    0.000    0.003    0.000 /opt/myenv/lib/python2.7/site-packages/django/template/base.py:200(create_token)
        6    0.002    0.000    0.002    0.000 /opt/myenv/lib/python2.7/site-packages/django/db/models/options.py:388(_fill_related_objects_cache)
    10187    0.002    0.000    0.002    0.000 /opt/myenv/lib/python2.7/stat.py:24(S_IFMT)
      621    0.002    0.000    0.004    0.000 /opt/myenv/lib/python2.7/site-packages/django/utils/functional.py:170(wrapper)
     1806    0.002    0.000    0.005    0.000 /usr/lib/python2.7/inspect.py:398(getfile)
     6224    0.002    0.000    0.002    0.000 /usr/lib/python2.7/string.py:220(lower)
     1150    0.002    0.000    0.027    0.000 /usr/lib/python2.7/inspect.py:460(getabsfile)
  394/273    0.002    0.000    0.002    0.000 /opt/myenv/lib/python2.7/site-packages/django/template/context.py:49(__getitem__)
      214    0.002    0.000    0.154    0.001 /usr/lib/python2.7/inspect.py:518(findsource)
        1    0.002    0.002    0.005    0.005 /opt/myenv/lib/python2.7/site-packages/django/core/urlresolvers.py:237(_populate)
      505    0.002    0.000    0.002    0.000 /opt/myenv/lib/python2.7/site-packages/django/utils/text.py:320(smart_split)
    59/21    0.002    0.000    0.004    0.000 /opt/myenv/lib/python2.7/sre_parse.py:379(_parse)
       59    0.001    0.000    0.006    0.000 /opt/myenv/lib/python2.7/site-packages/django/templatetags/i18n.py:281(do_translate)
       10    0.001    0.000    0.005    0.000 /opt/myenv/lib/python2.7/site-packages/django/template/base.py:188(tokenize)
   518/88    0.001    0.000    0.003    0.000 /usr/lib/python2.7/copy.py:145(deepcopy)
      214    0.001    0.000    0.160    0.001 /opt/myenv/lib/python2.7/site-packages/debug_toolbar/utils/__init__.py:101(getframeinfo)
      446    0.001    0.000    0.001    0.000 /opt/myenv/lib/python2.7/site-packages/django/utils/text.py:364(unescape_string_literal)
 ---- By file ----

      tottime
43.4%   0.102 /opt/myenv/lib/python2.7/posixpath.py
13.2%   0.031 /usr/lib/python2.7/inspect.py
 9.4%   0.022 /opt/myenv/lib/python2.7/site-packages/django/template/base.py
 6.8%   0.016 /opt/myenv/lib/python2.7/site-packages/django/db/backends/postgresql_psycopg2/base.py
 3.4%   0.008 /opt/myenv/lib/python2.7/linecache.py
 3.0%   0.007 /opt/myenv/lib/python2.7/stat.py
 3.0%   0.007 /opt/myenv/lib/python2.7/genericpath.py
 2.1%   0.005 /opt/myenv/lib/python2.7/site-packages/debug_toolbar/utils/tracking/db.py
 1.7%   0.004 /opt/myenv/lib/python2.7/sre_parse.py
 1.7%   0.004 /opt/myenv/lib/python2.7/site-packages/memcache.py
 1.3%   0.003 /opt/myenv/lib/python2.7/site-packages/django/utils/text.py
 1.3%   0.003 /opt/myenv/lib/python2.7/site-packages/django/core/urlresolvers.py
 0.9%   0.002 /usr/lib/python2.7/string.py
 0.9%   0.002 /opt/myenv/lib/python2.7/site-packages/django/utils/regex_helper.py
 0.9%   0.002 /opt/myenv/lib/python2.7/site-packages/django/utils/functional.py
 0.9%   0.002 /opt/myenv/lib/python2.7/site-packages/django/template/context.py
 0.9%   0.002 /opt/myenv/lib/python2.7/site-packages/django/db/models/options.py
 0.9%   0.002 /opt/myenv/lib/python2.7/site-packages/debug_toolbar/utils/__init__.py
 0.4%   0.001 /usr/lib/python2.7/copy.py
 0.4%   0.001 /opt/myenv/source/portal/myenv/views/__init__.py
 0.4%   0.001 /opt/myenv/lib/python2.7/sre_compile.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/utils/safestring.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/utils/importlib.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/utils/encoding.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/templatetags/i18n.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/template/loaders/app_directories.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/template/defaulttags.py
 0.4%   0.001 /opt/myenv/lib/python2.7/site-packages/django/db/models/base.py
 0.4%   0.001 /opt/myenv/lib/python2.7/encodings/utf_8.py
 0.0%   0.000 
 0.0%   0.000 /usr/lib/python2.7/uuid.py
 0.0%   0.000 /usr/lib/python2.7/urllib.py
 0.0%   0.000 /usr/lib/python2.7/threading.py
 0.0%   0.000 /usr/lib/python2.7/socket.py
 0.0%   0.000 /usr/lib/python2.7/pprint.py
 0.0%   0.000 /usr/lib/python2.7/multiprocessing/process.py
 0.0%   0.000 /usr/lib/python2.7/logging/handlers.py
 0.0%   0.000 /usr/lib/python2.7/logging/__init__.py
 0.0%   0.000 /usr/lib/python2.7/gettext.py
 0.0%   0.000 /usr/lib/python2.7/functools.py

As you can see, django-debug-toolbar and hotshots profiling middleware timings are very close.

What could be causing uWSGI to process the request for extra ~250ms after Django has rendered the template? I've tried enabling profiler option in uWSGI, but it generates information for hundred of thousands of calls and therefore rather hard to work with.

Any suggestions are appreciated.

Upvotes: 4

Views: 1464

Answers (1)

Jan Wrobel
Jan Wrobel

Reputation: 7109

I think the problem is that Profiling middleware does extensive processing that is not included in the profile time, but influences total request processing time.

The a look at the profiler middleware code. After profiler is closed, results are read from a temporary file (this can be a pretty big file in a binary format). Then results are processed and injected into response.

This additional processing can cause the difference you are seeing. Try running a benchmark with profiler disabled (do not pass ?prof in the URL) and see if nginx and uwsgi processing time improve.

Upvotes: 2

Related Questions