django - 在 uWSGI/Nginx 下分析 Django 应用程序

Question

我正在将一个中型 Django 1.4.2 应用程序迁移到新的基础设施，并尝试在新的、非常强大的硬件上优化系统的性能。我正在使用 django-debug-toolbar 以及基于热点的分析中间件来定位瓶颈，目前很难理解我从不同来源获得的执行时间值的差异。

例如，如果我对应用程序中的 URL 发出单个请求，并且将其映射到一个相当简单的 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 调试工具栏 - 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 处理额外的约 250 毫秒的请求？我尝试在 uWSGI 中启用分析器选项，但它会为数十万次调用生成信息，因此很难使用。

任何建议表示赞赏。

Answer 1

我认为问题在于 Profiling 中间件进行了不包括在分析时间中的广泛处理，但会影响总请求处理时间。

看看the profiler middleware code .关闭探查器后，将从临时文件中读取结果(这可能是二进制格式的相当大的文件)。然后处理结果并将其注入(inject)响应。

这种额外的处理可能会导致您看到的差异。尝试在禁用分析器的情况下运行基准测试(不要在 URL 中传递 ?prof)并查看 nginx 和 uwsgi 处理时间是否有所改善。