uWSGI/Nginx에서 Django 애플리케이션 프로파일 링

Question

중간 크기의 장고 1.4.2 애플리케이션을 새로운 인프라로 마이그레이션하고 새롭고 강력한 하드웨어에서 시스템 성능을 최적화하려고합니다. 나는 django-debug-toolbar와 hotshots 기반 프로파일 링 미들웨어를 사용하여 병목 현상을 찾아 내고 현재 다른 소스에서 얻은 실행 시간 값의 차이를 이해하는 데 어려움을 겪고 있습니다.

Nginx에 1.2.5 - 0.409s : 나는 오히려 간단한 뷰에 매핑 내 응용 프로그램에서 URL에 하나의 요청을 할 경우

는 예를 들어, 여기에 내가 얻을 타이밍이다

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 

장고 디버그 도구 모음 - 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가 템플릿을 렌더링 한 후 uWSGI가 250 밀리 초 동안 요청을 처리하게하는 원인은 무엇입니까? uWSGI에서 프로파일 러 옵션을 사용하도록 시도했지만, 수십만 건의 호출에 대한 정보를 생성하므로 작업하기가 다소 어렵습니다.

모든 의견을 환영합니다.

Answer 1

필자는 프로파일 링 미들웨어가 프로파일 시간에 포함되지 않지만 전체 요청 처리 시간에 영향을주는 광범위한 처리를한다는 점을 생각합니다.

보기는 the profiler middleware code입니다. 프로파일 러가 닫히면 결과는 임시 파일 (이 파일은 바이너리 형식의 꽤 큰 파일 일 수 있음)에서 읽습니다. 그런 다음 결과가 처리되고 응답으로 주입됩니다.

이 추가 처리로 인해 차이가 발생할 수 있습니다. 프로파일 러를 비활성화하고 (URL에 ?prof을 전달하지 마십시오) 벤치 마크를 실행하고 nginx 및 uwsgi 처리 시간이 개선되는지 확인하십시오.