Geek Answers Handbook

Profiling a Django application running uWSGI / Nginx

I am moving the medium-sized Django 1.4.2 application to a new infrastructure and trying to optimize system performance on new, very powerful hardware. I use the django-debug-toolbar as well as the hotshots-based profiling middleware to find bottlenecks and it is currently difficult to understand the difference in the runtime values ​​that I get from different sources.

For example, here are the timings that I get if I make one request to a URL in my application, are mapped to a fairly simple representation:

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 (64 bit) - 387 ms :

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

Django-debug-toolbar - 112.452 ms :

 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)

Middleware Profiling - 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 profile middleware time intervals are very close.

What can cause uWSGI to process the request for an extra ~ 250 ms after Django renders the template? I tried to enable the profiling option in uWSGI, but it generates information for hundreds of thousands of calls and is therefore quite difficult to work with.

Any suggestions are welcome.

+4
source share
1 answer

I think the problem is that the Profiling middleware performs extensive processing, which is not included in the profile time, but affects the processing time of the entire request.

Check out the middleware profiler code . After the profiler is closed, the results are read from a temporary file (this can be a fairly large binary file). Then the results are processed and entered into the response.

This extra processing may cause the difference you see. Try running the test with the profiler disabled (don’t miss ?prof in the URL) and see if the processing time of nginx and uwsgi improves.

+2
source

More articles:


All Articles