MySQL server has gone away报错
最近碰到MySQL server has gone away的报错,报错出现的现象是:
生产环境周末到周一上午会出现一些间断的报错,晚些恢复正常
测试环境每天上午会出现间断报错,晚些恢复正常
出错的场景都是通过ThreadPoolExecutor执行的异步任务中执行mysql查询操作,其他查询操作正常
只有一部分异步任务会出现报错,一部分执行正常
项目基本情况:基于python3.5+django1.8,数据库mysql,生产和测试环境都是通过nginx+uwsgi部署
分析原因
谷歌了一下MySQL server has gone away问题可能的原因:
MySQL服务宕了
连接超时
进程在server端被主动kill
SQL语句太长
再结合项目实际情况逐条分析:
首先第一条,“MySQL服务宕了”,查看mysql的报错日志,看有没有重启信息,同时查看mysql的运行时长。
mysql> show global status like 'uptime';
+---------------+----------+
| Variable_name | Value |
+---------------+----------+
| Uptime | 13881221 |
+---------------+----------+
1 row in set (0.00 sec)
报错日志中并没有服务重启的信息,同时uptime值很大,表示已经运行很长时间。因此第一条原因可以排除
第三条,“进程在server端被主动kill”,当有长时间的慢查询时执行kill导致。查一下慢查询数量。
mysql> show global status like 'com_kill';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_kill | 12 |
+---------------+-------+
1 row in set (0.00 sec)
Com_kill居然有这么多-_-||,但也不确定出错的查询语句是否是慢查询。找了一下报错代码的查询语句,属于索引查询,而且查询时间不超过100ms,因此,这一条也可以排除。
第四条,SQL语句太长导致。直接找到报错的查询语句,属于普通查询长度,所以这一条应该也可以排除。
那么第二条,连接超时,当某个连接很长时间没有新的请求了,达到了mysql服务器的超时时间,被强行关闭,再次使用该连接时,其实已经失效,就会出现"MySQL server has gone away"的报错了。首先看一下数据库连接的最大超时时间设置多大。
mysql> show global variables like 'wait_timeout';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wait_timeout | 86400 |
+---------------+-------+
1 row in set (0.00 sec)
目前设置的最大超时时间是24小时,也就是在这24小时内有数据库连接超时,超时连接后面又被用到,导致报错。
之前在django数据库连接中分析了django的数据库连接是基于线程(thread.local)创建的全局变量,即线程本地变量,下面简称为线程变量。
对于常规请求,要获取数据库连接时,会首先查看当前线程变量中是否有可用连接,没有就创建并保存到线程变量中。每个request在开始和结束之前,会检查当前线程的数据库连接是否可用,并关闭不可用连接。这样就保证了每次请求获取到的一定是可用的数据库连接。
对于基于ThreadPoolExecutor的异步任务,线程池是在项目启动时创建的,当其中的线程被调起执行异步任务时,首次查询数据库时创建数据库连接,后续会一直保存在该异步线程中,该线程也会一直保存在线程池中。
由于没有像常规请求一样的在开始和结束之前检查数据库连接是否可用的机制,线程池中的线程保存的数据库连接也许是不可用的,就导致下次被调起执行数据库操作时出现“MySQL server has gone away”的报错。
再结合出错现象分析一下:
每到周末,生产环境活跃的用户数量减少,尤其是涉及到异步任务的业务场景触发减少,所以到周末线程池中的线程保存的部分数据库连接闲置超过24小时,周一上班后用户活跃增加,失效连接被调起,自然就会报错了。
线程池中的每个线程被调起的时机和次数都不同,某些线程最近刚被调起过,某些线程长时间没被调起,所以数据库连接失效,因此会出现部分异步任务报错的现象。
出现报错后一段时间自己恢复正常,而ThreadPoolExecutor本身也没有断掉异常连接或者杀掉线程的机制,但是查看业务日志,发现恢复正常后执行异步任务的线程和之前报错的线程不同,也就是基于某种机制,之前的线程被kill了。
看一下ThreadPoolExecutor中创建线程的逻辑:
def _adjust_thread_count(self):
# When the executor gets lost, the weakref callback will wake up
# the worker threads.
def weakref_cb(_, q=self._work_queue):
q.put(None)
# TODO(bquinlan): Should avoid creating new threads if there are more
# idle threads than items in the work queue.
if len(self._threads) < self._max_workers:
t = threading.Thread(target=_worker,
args=(weakref.ref(self, weakref_cb),
self._work_queue))
# 线程被设为守护线程
t.daemon = True
t.start()
self._threads.add(t)
_threads_queues[t] = self._work_queue
线程池中创建的线程属于守护线程,当主线程退出,子线程也会跟着退出。而子线程是在调用submit方法提交异步任务时,若线程池中实际线程数量小于指定数量,便会创建。因此主线程是请求线程。
在用uWSGI部署的django项目中,请求线程是由uWSGI分配的。uWSGI会根据配置文件中的process, threads参数决定开多少工作进程和子线程,同时还有max-requests参数,表示为每个工作进程设置的请求数上限。
当该工作进程请求数达到这个值,就会被回收重用(重启),其子线程也会重启。所以上面的报错现象中,其实是工作进程重启了,请求子线程也会重建,导致线程池中的守护线程也会被kill了,报错就停止了。
总结一下原因:
由于django的数据库连接是保存到线程本地变量中的,通过ThreadPoolExecutor创建的线程会保存各自的数据库连接。当连接被保存的时间超过mysql连接的最大超时时间,连接失效,但不会被线程释放。之后再调起线程执行涉及到数据库操作的异步任务时,会用到失效的数据库连接,导致报错。
又由于uWSGI的工作进程达到max-requests数量而重启,导致请求线程重启,线程池中的线程是根据请求线程创建的守护线程,因此会被kill,所以后面自己恢复正常。
解决方案
要解决这个问题,最直接的办法是在线程池的所有异步任务中,在执行数据库操作之前,检查数据库连接是否可用,然后关掉不可用连接。
from threading import local
def close_old_connections():
# 获取当前线程本地变量
connections = local()
# 根据数据库别名获取数据库连接
if hasattr(connections, 'default'):
conn = getattr(connections, 'default')
# 检查连接可用性,并关闭不可用连接
conn.close_if_unusable_or_obsolete()
或者改写一下django获取和保存数据库连接的机制,可以创建一个全局的数据库连接池,不管是常规请求还是异步任务,都从连接池获取数据库连接,由连接池保证数据库连接的数量和可用性。