问题表现就是使用Django的ORM读写数据库时经常会抛出下面的异常
db instance (fdbd:dc02:ff:2:1:226:4:211:3306) is unavailable, ex is (2013, 'Lost connection to MySQL server during query ([Errno 104] Connection reset by peer)')
先说结论:
- Django中在视图中如果开启了异步线程,线程中有数据库操作,要主动关闭连接;
- wsgi中间件要保证能够调用HttpResponseBase的close方法。
排查过程:
直接使用错误关键字搜索,得到一些解决方法是增加一些延迟参数,或者优化慢查询什么的,直觉看起来不像是我这里的根因问题,因为上面这个异常日志大部分都没有影响到服务端正常响应(即在接口响应层面没有抛出异常),却在周末的几个时间段,服务接口响应频繁抛出这个异常,但周末服务QPS很低,数据库正常情况下负载应该也很低,当时也没有慢查询,因此只能想办法看看是不是对应时间段有什么监控能发现问题。
经过一番查看终于发现了一个监控能够和异常时间点对应上,就是数据库代理的前端限流监控,发现在对应时间段我的服务连接数很多一直被限流导致抛出异常,然后查看我的服务连接数,发现非常高:
而18:00的连接数骤降是因为当时增加日志有个服务升级,因此可以断定是django服务连接数太多了。
定位到问题原因后,就是再找为什么连接那么高了,经过和豆包的一番交流,得到的信息是Django在视图处理函数里会清理关闭连接,但如果是有异步线程,则不一定会清理了,联想到服务接口确实有大量异步线程处理,且没有主动关闭连接,因此再次交流得到如下的装饰器,都加在异步函数中:
def manage_db_connections(func):
@wraps(func)
def wrapper(*args, **kwargs):
try:
close_old_connections() # 清理过期连接
return func(*args, **kwargs)
finally:
# 释放所有连接
for alias in connections:
connections[alias].close()
return wrapper
感觉好像没什么问题了,但观察了一天后发现连接数又逐渐上来了:
看起来还是没有关闭连接,但异步线程的连接已经主动关闭了,只剩下一个排查点是视图函数的连接是否关闭了,还好Django是开源的,可以直接对源码打断点,通过代码跳转找到关闭连接的地方打上断点,然后发送请求看断点是否执行,测试了几次发现只在请求进入的时候有执行,完成的时候没有调用,结合下面信号的代码感觉是信号没生效,问了豆包聊了会也没说明白咋回事,后来想到下面代码是connect,找找看发送在哪,看看是不是发送了
然后到django源码中搜了下request_finished.send,就会发现只有一个地方调用了
那就好办些了,回到服务代码,通过跳转找出来这个文件,在close处打断点,发现根本没执行这个函数,然后结合着上面有个关于wsgi的注释,联想到wsgi确实增加了一个自定义中间件,因此先去掉中间件恢复原来的试试
把wsgi的19行注释掉,取消18行的注释,重新执行发现没问题,反向操作发现不调用,那可以断定就是新增的自定义Middleware的问题了
豆包一番长聊后,找到原因是因为Middleware没有主动调用response的close(__call__方法里没有close),而在Django源码中也能看到对应的281行注释,wsgi中间件必须要调用close方法
最后经过对中间件的__call__方法修改,主动调用close后,问题得以解决,连接数经过持续观察后,也稳定在几十到一百的数量。