Reputation: 1051
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
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