Django WSGI 多线程和连接问题

Question

我按照Graham的指示，用mod_wsgi把Apache和Django整合在一起，但还是遇到了连接和响应时间的问题。这些问题是随机发生的，而且Apache的日志文件里没有任何错误，所以我很难搞清楚到底发生了什么。

我的Apache是用预先分叉的方式构建的，配置如下：

<IfModule prefork.c>
StartServers       8
MinSpareServers    5
MaxSpareServers   20
ServerLimit      256
MaxClients       256
MaxRequestsPerChild 0
</IfModule>

与WSGI相关的配置：

LogLevel info
LoadModule wsgi_module modules/mod_wsgi.so
WSGISocketPrefix run/wsgix
WSGIDaemonProcess somename user=apache group=apache threads=25 processes=1
WSGIScriptAlias / /wsgi-dir/script.wsgi
WSGIImportScript /wsgi-dir/script.wsgi process-group=somename application-group=%{GLOBAL}

<Directory /wsgi-dir/script.wsgi>
   Order deny,allow
   Allow from all
   WSGIProcessGroup  somename
</Directory>

在请求处理器中，我使用以下方法来监控活跃线程：

logger.info("Active threads: {0}".format(threading.active_count()))

我注意到，尽管我在配置中设置了最多25个线程，但活跃线程的数量从来没有超过4。同时，有些客户端可能需要等待超过1分钟才能建立新连接，而请求处理的时间大约是2秒。

如果请求能到达服务器，处理速度很快，但有些情况下（大约每100个请求中有1个），客户端只是等待连接，有时甚至会因为Apache的限制而超时：

Timeout 60 

我觉得这种情况在网络应用中可能不太容易被注意到，因为每100个请求中有1个并不算太重要（用户可以刷新页面），但在服务的世界里，这确实是个问题。

我不明白的是，如果所有线程都在忙着服务其他客户端，为什么Django不再生成一个新的线程？如果不是线程的问题，那可能是什么呢？是Graham提到的应用重载问题吗？

这是我的版本：

python26-2.6.8-3.30.amzn1.x86_64
Django-1.4.3
mod_wsgi-3.2-1.6.amzn1.x86_64
Server version: Apache/2.2.23 (Unix)
Server loaded:  APR 1.4.6, APR-Util 1.4.1
Compiled using: APR 1.4.6, APR-Util 1.4.1
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)

================== 第一次更新，已实施Graham的建议 ================================

Graham等人，

感谢你们的评论和建议。我检查了mod_wsgi的版本，是3.2（见上文）。我的WSGI配置现在看起来如下：

LogLevel info
LoadModule wsgi_module modules/mod_wsgi.so
WSGISocketPrefix run/wsgix
WSGIDaemonProcess somename user=apache group=apache threads=25
WSGIScriptAlias /  /wsgi-dir/script.wsgi process-group=somename application-group=%{GLOBAL}

<Directory /wsgi-dir>
   Order deny,allow
   Allow from all
</Directory>

只要启动50个EC2客户端，每个客户端在启动时发送几条消息，就能看到一个客户端的延迟达到49秒，而其他客户端的平均响应时间是2.2秒，最长为7秒。

我查看了应用的日志文件，发现延迟请求的“请求接收”和“响应发送”之间的时间差是0.16秒，而从客户端的角度看却是49秒的延迟。

这让我们有两种可能性：

1. 一个客户端几乎花了49秒才建立连接
2. 连接已经建立，但服务器（实际上是Django/WSGI内部）无法快速读取请求。

很难判断是第1种还是第2种，因为我在客户端使用了Python的“requests”模块来连接服务。我觉得是第2种，因为如果延迟超过64-65秒，Apache的发送/接收超时就会触发，我在Apache的日志文件中看到了这一点。

接下来我会尝试做以下事情来进一步澄清：

1. 创建一个简单的控制器，如下所示：

   def listener(request):

   logger.info("Started, active threads: {0}".format(threading.active_count()))    
   time.sleep(3)
   logger.info("Finished, active threads: {0}".format(threading.active_count()))    
   return HttpResponse('OK')
   

注意：记录器也会记录时间。

1. 创建一个简单的统计接口（我不想在所有客户端的EC2上分析日志）：

   def log(request):

   id = request.REQUEST['id']
   time = request.REQUEST['time']
   res = request.REQUEST['res']
   
   if (id and time):
       logger.info("STAT Instance: {0}, Processing time: {1}, Response: {2}".format(id,time,res))
   
   return HttpResponse('OK')
   

客户端的工作方式如下：

1. 向“listener” URL发送几条请求，并在客户端计算处理时间

2. 将处理时间和EC2实例ID一起发送到“log” URL

   如果我能通过这种简单的方法重现问题，那就能复现了，我希望Django团队能从这里继续处理。

任何其他建议也非常欢迎。非常感谢所有回答过的人。

================== 第二次更新，关于建议的测试 ================================

我已经实现了建议的监听器，并能够重现这个问题，希望其他人也能做到这一点——你只需要一个AWS账户，就能启动大量的EC2客户端——通常50个就足够了，但有时我需要增加到100个才能看到延迟。

有趣的是，在这个测试中，活跃线程的数量从1逐渐增加到8，这可能是因为服务器上的平均处理时间增加了，所以确实有效，但仍然不足以防止延迟。

我把客户端的脚本放在EC2的用户数据中，下面是它的样子。如果你需要关于如何创建一个自动扩展组来管理这些客户端的快速说明，请告诉我。

#!/bin/bash

do_send() {

        d1=`date +%s`
        res=`python ~ec2-user/client/fetch.py ${URL_ROOT}/init/`
        res=`echo $res | tr '\n' ' ' | tr ' ' +`
        d2=`date +%s`
        delta=`expr $d2 - $d1`
        echo $ami $ins $res $delta >>$LOG
        curl -s  "${URL_ROOT}/stat/?id=$ami&time=$delta&res=$ins:$res" >/dev/null 2>&1
}

URL_ROOT=<SERVICE-ROOT_URL>
LOG=~ec2-user/log.txt

ins=`curl -s http://169.254.169.254/latest/meta-data/instance-id 2>/dev/null`
ami=`curl -s http://169.254.169.254/latest/meta-data/ami-id 2>/dev/null`
echo "Instance=[$ins]" >$LOG

# First request
do_send

# Second request
do_send

fetch.py客户端的样子如下：

@author: ogryb
'''
import requests
import datetime
import socket

from optparse import OptionParser
usage = "usage: %prog [options] init_url\n   init_url - http://<host>/init/ server's address"
parser = OptionParser(usage=usage)
parser.add_option("-i", "--id", dest="id",
                  help="instance ID", metavar="STRING")
parser.add_option("-p", "--phost", dest="phost",
                  help="public hostname", metavar="STRING")
parser.add_option("-l", "--lhost", dest="lhost",
                  help="local hostname", metavar="STRING")
parser.add_option("-t", "--type", dest="type",
                  help="instance type", metavar="STRING")
parser.add_option("-q", "--quiet",
                  action="store_true", dest="quiet", default=False,
                  help="Quiet mode")
(opt, args) = parser.parse_args()
ip = socket.gethostbyname(socket.gethostname())
if (not opt.quiet):
    print ("=== Getting metadata:\t{0} {1}".format(datetime.datetime.utcnow(), ip))
if not opt.id:
    r = requests.get(url='http://169.254.169.254/latest/meta-data/instance-id')
    opt.id = r.text
if not opt.phost:
    r = requests.get(url='http://169.254.169.254/latest/meta-data/public-hostname')
    opt.phost = r.text
if not opt.lhost:
    r = requests.get(url='http://169.254.169.254/latest/meta-data/local-hostname')
    opt.lhost = r.text
if not opt.type:
    r = requests.get(url='http://169.254.169.254/latest/meta-data/instance-type')
    opt.type = r.text
body = "id={0}&phost={1}&lhost={2}&type={3}".format(opt.id, opt.phost, opt.lhost, opt.type)
if (not opt.quiet):
    print ("=== Start sending:\t{0} {1} {2}".format(datetime.datetime.utcnow(), ip, opt.id))
r = requests.post(url=args[0], data=body, verify=False)
if (not opt.quiet):
    print ("=== End sending:\t{0} {1} {2}".format(datetime.datetime.utcnow(), ip, opt.id))
print r.text
if (not opt.quiet):
    print "Request Body={0} url={1}".format(body,args[0])
    print "Response: {0}\n{1}".format(r.status_code, r.text)

============ 03/19/13 - 23:45 错误日志的附加信息 ===

我把Apache的日志级别改成了调试，发现Apache的错误日志中有以下内容。请告诉我这是否可能是延迟的原因，以及该怎么解决。我在某处读到“KeyError”是无害的，但你永远不知道。

一个客户端在6:37:28时延迟了41秒。错误日志中最近的事件发生在06:37:15：

Wed Mar 20 06:37:15 2013] [info] mod_wsgi (pid=27005): Initializing Python.
[Wed Mar 20 06:37:15 2013] [info] mod_wsgi (pid=27005): Attach interpreter '

完整的错误日志如下：

Wed Mar 20 06:29:45 2013] [info] Server built: Oct 21 2012 20:35:32
[Wed Mar 20 06:29:45 2013] [debug] prefork.c(1023): AcceptMutex: sysvsem (default: sysvsem)
[Wed Mar 20 06:29:45 2013] [info] mod_wsgi (pid=26891): Attach interpreter ''.
[Wed Mar 20 06:29:45 2013] [info] mod_wsgi (pid=26892): Attach interpreter ''.
[Wed Mar 20 06:29:45 2013] [info] mod_wsgi (pid=26893): Attach interpreter ''.
[Wed Mar 20 06:29:45 2013] [info] mod_wsgi (pid=26895): Attach interpreter ''.
[Wed Mar 20 06:29:45 2013] [info] mod_wsgi (pid=26894): Attach interpreter ''.
[Wed Mar 20 06:37:15 2013] [debug] proxy_util.c(1820): proxy: grabbed scoreboard slot 0 in child 27005 for worker proxy:reverse
[Wed Mar 20 06:37:15 2013] [debug] proxy_util.c(1839): proxy: worker proxy:reverse already initialized
[Wed Mar 20 06:37:15 2013] [debug] proxy_util.c(1936): proxy: initialized single connection worker 0 in child 27005 for (*)
[Wed Mar 20 06:37:15 2013] [info] mod_wsgi (pid=27005): Initializing Python.
[Wed Mar 20 06:37:15 2013] [info] mod_wsgi (pid=27005): Attach interpreter ''.
[Wed Mar 20 06:38:10 2013] [debug] proxy_util.c(1820): proxy: grabbed scoreboard slot 0 in child 27006 for worker proxy:reverse
[Wed Mar 20 06:38:10 2013] [debug] proxy_util.c(1839): proxy: worker proxy:reverse already initialized
[Wed Mar 20 06:38:10 2013] [debug] proxy_util.c(1936): proxy: initialized single connection worker 0 in child 27006 for (*)
[Wed Mar 20 06:38:10 2013] [info] mod_wsgi (pid=27006): Initializing Python.
[Wed Mar 20 06:38:10 2013] [info] mod_wsgi (pid=27006): Attach interpreter ''.
[Wed Mar 20 06:38:11 2013] [info] mod_wsgi (pid=26874): Destroying interpreters.
[Wed Mar 20 06:38:11 2013] [info] mod_wsgi (pid=26874): Cleanup interpreter ''.
[Wed Mar 20 06:38:11 2013] [info] mod_wsgi (pid=26874): Terminating Python.
[Wed Mar 20 06:38:11 2013] [error] Exception KeyError: KeyError(140627014572000,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Wed Mar 20 06:38:11 2013] [info] mod_wsgi (pid=26874): Python has shutdown.
[Wed Mar 20 06:38:44 2013] [debug] proxy_util.c(1820): proxy: grabbed scoreboard slot 0 in child 27007 for worker proxy:reverse
[Wed Mar 20 06:38:44 2013] [debug] proxy_util.c(1839): proxy: worker proxy:reverse already initialized
[Wed Mar 20 06:38:44 2013] [debug] proxy_util.c(1936): proxy: initialized single connection worker 0 in child 27007 for (*)
[Wed Mar 20 06:38:44 2013] [info] mod_wsgi (pid=27007): Initializing Python.
[Wed Mar 20 06:38:44 2013] [info] mod_wsgi (pid=27007): Attach interpreter ''.
[Wed Mar 20 06:38:45 2013] [info] mod_wsgi (pid=26880): Destroying interpreters.
[Wed Mar 20 06:38:45 2013] [info] mod_wsgi (pid=26880): Cleanup interpreter ''.
[Wed Mar 20 06:38:45 2013] [info] mod_wsgi (pid=26880): Terminating Python.
[Wed Mar 20 06:38:45 2013] [error] Exception KeyError: KeyError(140627014572000,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Wed Mar 20 06:38:45 2013] [info] mod_wsgi (pid=26880): Python has shutdown.

Answer 1

抱歉回复得晚了，也没提供太多细节，但这并不是Django或Apache的问题。问题出在运行它的环境上。我知道“环境”到底出了什么问题，但因为保密协议不能透露更多细节。希望你能理解我说的“环境”是什么意思。

再给你一个提示：我在最初的帖子中假设是#2，其实我错了，实际上是#1。

我觉得知道这不是Django或Apache的问题，对那些还在研究这个问题的人来说是个很大的帮助。我不在乎这个回答会被多少人点踩或点赞，只是想帮忙，因为我知道研究这些问题需要花费很多时间。

谢谢。

Answer 2

配置如下：

<Directory /wsgi-dir/script.wsgi>
   Order deny,allow
   Allow from all
   WSGIProcessGroup  somename
</Directory>

应该是：

<Directory /wsgi-dir>
   Order deny,allow
   Allow from all
   WSGIProcessGroup  somename
   WSGIApplicationGroup %{GLOBAL}
</Directory>

作为开始。

你现在的WSGI应用在处理请求时是以嵌入模式运行，而不是守护进程模式。这是因为目录指令的路径不对，应该是一个目录，但你用的却不是。你不能像现在这样使用文件路径。你应该检查一下它运行的位置，可以用以下链接：

• http://code.google.com/p/modwsgi/wiki/CheckingYourInstallation#Embedded_Or_Daemon_Mode

同时，你在守护进程模式下加载了一个多余的副本，但这个副本并没有被使用，因为WSGIImportScript的原因。

即使你修正了指令路径，预加载的内容也在不同的子解释器中，而请求是在另一个地方处理的。你需要像上面提到的那样使用WSGIApplicationGroup，以确保它们在同一个子解释器（应用组）中。

如果你使用的是mod_wsgi 3.0及以上版本，最好删除WSGIImportScript指令，改用：

WSGIScriptAlias / /wsgi-dir/script.wsgi process-group=somename application-group=%{GLOBAL}

<Directory /wsgi-dir>
   Order deny,allow
   Allow from all
</Directory>

同时在WSGIScriptAlias中指定进程组和应用组，这样就不需要单独的WSGIProcessGroup和WSGIApplicationGroup了。指定这两个也会有一个副作用，就是预加载脚本，这样就替代了WSGIImportScript的功能，因此可以删除WSGIImportScript。

至于请求为什么这么慢，你可以安装并尝试New Relic，看看问题出在哪里。

关于一般的Apache配置，我建议你看看我在PyCon US会议上做的演讲幻灯片：

• http://www.slideshare.net/GrahamDumpleton/pycon-us-2013-making-apache-suck-less-for-hosting-python-web-applications

视频应该在本周末之前发布。

我去年在PyCon的演讲也会很有趣。

• http://lanyrd.com/2012/pycon/spcdg/