中規模の Django 1.4.2 アプリケーションを新しいインフラストラクチャに移行し、新しい非常に強力なハードウェアでシステムのパフォーマンスを最適化しようとしています。私は django-debug-toolbar と hotshots ベースのプロファイリング ミドルウェアを使用してボトルネックを特定していますが、現在、さまざまなソースから取得した実行時間の値の違いを理解するのに苦労しています。
たとえば、かなり単純なビューにマップされたアプリケーションで URL に単一のリクエストを行った場合のタイミングは次のとおりです。
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ビット) - 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 ミリ秒:
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)
プロファイリング ミドルウェア - 0.132 秒:
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
ご覧のとおり、django-debug-toolbar と hotshots プロファイリング ミドルウェアのタイミングは非常に近いです。
Django がテンプレートをレンダリングした後、uWSGI が余分な ~250ms のリクエストを処理する原因は何ですか? uWSGI でプロファイラー オプションを有効にしようとしましたが、何十万回もの呼び出しに関する情報が生成されるため、操作がかなり困難です。
任意の提案をいただければ幸いです。