原文鏈接：MySQL-server-has-gone-away-in-django-ThreadPoolExecutor
MySQL server has gone away報(bào)錯(cuò)
最近碰到MySQL server has gone away的報(bào)錯(cuò)，報(bào)錯(cuò)出現(xiàn)的現(xiàn)象是：
- 生產(chǎn)環(huán)境周末到周一上午會(huì)出現(xiàn)一些間斷的報(bào)錯(cuò)孝宗，晚些恢復(fù)正常
- 測(cè)試環(huán)境每天上午會(huì)出現(xiàn)間斷報(bào)錯(cuò)，晚些恢復(fù)正常
- 出錯(cuò)的場(chǎng)景都是通過
ThreadPoolExecutor執(zhí)行的異步任務(wù)中執(zhí)行mysql查詢操作，其他查詢操作正常 - 只有一部分異步任務(wù)會(huì)出現(xiàn)報(bào)錯(cuò)烹植，一部分執(zhí)行正常
項(xiàng)目基本情況：基于python3.5+django1.8叠纷，數(shù)據(jù)庫mysql肮蛹，生產(chǎn)和測(cè)試環(huán)境都是通過nginx+uwsgi部署
分析原因
谷歌了一下MySQL server has gone away問題可能的原因：
-
MySQL服務(wù)宕了 - 連接超時(shí)
- 進(jìn)程在
server端被主動(dòng)kill -
SQL語句太長(zhǎng)
再結(jié)合項(xiàng)目實(shí)際情況逐條分析：
- 首先第一條勺择，“
MySQL服務(wù)宕了”创南，查看mysql的報(bào)錯(cuò)日志伦忠，看有沒有重啟信息，同時(shí)查看mysql的運(yùn)行時(shí)長(zhǎng)稿辙。
mysql> show global status like 'uptime';
+---------------+----------+
| Variable_name | Value |
+---------------+----------+
| Uptime | 13881221 |
+---------------+----------+
1 row in set (0.00 sec)
報(bào)錯(cuò)日志中并沒有服務(wù)重啟的信息昆码，同時(shí)uptime值很大，表示已經(jīng)運(yùn)行很長(zhǎng)時(shí)間邻储。因此第一條原因可以排除
- 第三條赋咽，“進(jìn)程在
server端被主動(dòng)kill”，當(dāng)有長(zhǎng)時(shí)間的慢查詢時(shí)執(zhí)行kill導(dǎo)致吨娜。查一下慢查詢數(shù)量脓匿。
mysql> show global status like 'com_kill';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_kill | 12 |
+---------------+-------+
1 row in set (0.00 sec)
Com_kill居然有這么多-_-||，但也不確定出錯(cuò)的查詢語句是否是慢查詢宦赠。找了一下報(bào)錯(cuò)代碼的查詢語句陪毡，屬于索引查詢，而且查詢時(shí)間不超過100ms勾扭，因此毡琉，這一條也可以排除。
第四條腻脏，
SQL語句太長(zhǎng)導(dǎo)致弱判。直接找到報(bào)錯(cuò)的查詢語句心包，屬于普通查詢長(zhǎng)度，所以這一條應(yīng)該也可以排除丐谋。那么第二條，連接超時(shí)煌珊，當(dāng)某個(gè)連接很長(zhǎng)時(shí)間沒有新的請(qǐng)求了笋鄙，達(dá)到了
mysql服務(wù)器的超時(shí)時(shí)間，被強(qiáng)行關(guān)閉怪瓶，再次使用該連接時(shí)萧落，其實(shí)已經(jīng)失效践美，就會(huì)出現(xiàn)"MySQL server has gone away"的報(bào)錯(cuò)了。首先看一下數(shù)據(jù)庫連接的最大超時(shí)時(shí)間設(shè)置多大找岖。
mysql> show global variables like 'wait_timeout';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wait_timeout | 86400 |
+---------------+-------+
1 row in set (0.00 sec)
目前設(shè)置的最大超時(shí)時(shí)間是24小時(shí)陨倡，也就是在這24小時(shí)內(nèi)有數(shù)據(jù)庫連接超時(shí)，超時(shí)連接后面又被用到许布，導(dǎo)致報(bào)錯(cuò)兴革。
之前在django數(shù)據(jù)庫連接中分析了django的數(shù)據(jù)庫連接是基于線程(thread.local)創(chuàng)建的全局變量，即線程本地變量蜜唾，下面簡(jiǎn)稱為線程變量杂曲。
- 對(duì)于常規(guī)請(qǐng)求，要獲取數(shù)據(jù)庫連接時(shí)袁余，會(huì)首先查看當(dāng)前線程變量中是否有可用連接擎勘，沒有就創(chuàng)建并保存到線程變量中。每個(gè)
request在開始和結(jié)束之前颖榜，會(huì)檢查當(dāng)前線程的數(shù)據(jù)庫連接是否可用棚饵，并關(guān)閉不可用連接。這樣就保證了每次請(qǐng)求獲取到的一定是可用的數(shù)據(jù)庫連接掩完。 - 對(duì)于基于
ThreadPoolExecutor的異步任務(wù)噪漾，線程池是在項(xiàng)目啟動(dòng)時(shí)創(chuàng)建的，當(dāng)其中的線程被調(diào)起執(zhí)行異步任務(wù)時(shí)且蓬，首次查詢數(shù)據(jù)庫時(shí)創(chuàng)建數(shù)據(jù)庫連接欣硼，后續(xù)會(huì)一直保存在該異步線程中，該線程也會(huì)一直保存在線程池中恶阴。
由于沒有像常規(guī)請(qǐng)求一樣的在開始和結(jié)束之前檢查數(shù)據(jù)庫連接是否可用的機(jī)制诈胜，線程池中的線程保存的數(shù)據(jù)庫連接也許是不可用的，就導(dǎo)致下次被調(diào)起執(zhí)行數(shù)據(jù)庫操作時(shí)出現(xiàn)“MySQL server has gone away”的報(bào)錯(cuò)存淫。
再結(jié)合出錯(cuò)現(xiàn)象分析一下：
- 每到周末耘斩，生產(chǎn)環(huán)境活躍的用戶數(shù)量減少，尤其是涉及到異步任務(wù)的業(yè)務(wù)場(chǎng)景觸發(fā)減少桅咆，所以到周末線程池中的線程保存的部分?jǐn)?shù)據(jù)庫連接閑置超過24小時(shí)括授，周一上班后用戶活躍增加，失效連接被調(diào)起岩饼，自然就會(huì)報(bào)錯(cuò)了荚虚。
- 線程池中的每個(gè)線程被調(diào)起的時(shí)機(jī)和次數(shù)都不同，某些線程最近剛被調(diào)起過籍茧，某些線程長(zhǎng)時(shí)間沒被調(diào)起版述，所以數(shù)據(jù)庫連接失效，因此會(huì)出現(xiàn)部分異步任務(wù)報(bào)錯(cuò)的現(xiàn)象寞冯。
- 出現(xiàn)報(bào)錯(cuò)后一段時(shí)間自己恢復(fù)正常渴析，而
ThreadPoolExecutor本身也沒有斷掉異常連接或者殺掉線程的機(jī)制晚伙，但是查看業(yè)務(wù)日志，發(fā)現(xiàn)恢復(fù)正常后執(zhí)行異步任務(wù)的線程和之前報(bào)錯(cuò)的線程不同俭茧，也就是基于某種機(jī)制咆疗，之前的線程被kill了。
看一下ThreadPoolExecutor中創(chuàng)建線程的邏輯：
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))
# 線程被設(shè)為守護(hù)線程
t.daemon = True
t.start()
self._threads.add(t)
_threads_queues[t] = self._work_queue
線程池中創(chuàng)建的線程屬于守護(hù)線程母债，當(dāng)主線程退出午磁，子線程也會(huì)跟著退出。而子線程是在調(diào)用submit方法提交異步任務(wù)時(shí)毡们，若線程池中實(shí)際線程數(shù)量小于指定數(shù)量迅皇，便會(huì)創(chuàng)建。因此主線程是請(qǐng)求線程衙熔。
在用uWSGI部署的django項(xiàng)目中登颓，請(qǐng)求線程是由uWSGI分配的。uWSGI會(huì)根據(jù)配置文件中的process, threads參數(shù)決定開多少工作進(jìn)程和子線程青责，同時(shí)還有max-requests參數(shù)挺据，表示為每個(gè)工作進(jìn)程設(shè)置的請(qǐng)求數(shù)上限取具。
當(dāng)該工作進(jìn)程請(qǐng)求數(shù)達(dá)到這個(gè)值脖隶，就會(huì)被回收重用（重啟），其子線程也會(huì)重啟暇检。所以上面的報(bào)錯(cuò)現(xiàn)象中产阱，其實(shí)是工作進(jìn)程重啟了，請(qǐng)求子線程也會(huì)重建块仆，導(dǎo)致線程池中的守護(hù)線程也會(huì)被kill了构蹬，報(bào)錯(cuò)就停止了。
總結(jié)一下原因：
- 由于
django的數(shù)據(jù)庫連接是保存到線程本地變量中的悔据，通過ThreadPoolExecutor創(chuàng)建的線程會(huì)保存各自的數(shù)據(jù)庫連接庄敛。當(dāng)連接被保存的時(shí)間超過mysql連接的最大超時(shí)時(shí)間，連接失效科汗，但不會(huì)被線程釋放藻烤。之后再調(diào)起線程執(zhí)行涉及到數(shù)據(jù)庫操作的異步任務(wù)時(shí)，會(huì)用到失效的數(shù)據(jù)庫連接头滔，導(dǎo)致報(bào)錯(cuò)怖亭。 - 又由于
uWSGI的工作進(jìn)程達(dá)到max-requests數(shù)量而重啟，導(dǎo)致請(qǐng)求線程重啟坤检，線程池中的線程是根據(jù)請(qǐng)求線程創(chuàng)建的守護(hù)線程兴猩，因此會(huì)被kill，所以后面自己恢復(fù)正常早歇。
解決方案
要解決這個(gè)問題倾芝，最直接的辦法是在線程池的所有異步任務(wù)中讨勤，在執(zhí)行數(shù)據(jù)庫操作之前，檢查數(shù)據(jù)庫連接是否可用晨另，然后關(guān)掉不可用連接悬襟。
from threading import local
def close_old_connections():
# 獲取當(dāng)前線程本地變量
connections = local()
# 根據(jù)數(shù)據(jù)庫別名獲取數(shù)據(jù)庫連接
if hasattr(connections, 'default'):
conn = getattr(connections, 'default')
# 檢查連接可用性，并關(guān)閉不可用連接
conn.close_if_unusable_or_obsolete()
或者改寫一下django獲取和保存數(shù)據(jù)庫連接的機(jī)制拯刁，可以創(chuàng)建一個(gè)全局的數(shù)據(jù)庫連接池脊岳，不管是常規(guī)請(qǐng)求還是異步任務(wù)，都從連接池獲取數(shù)據(jù)庫連接垛玻，由連接池保證數(shù)據(jù)庫連接的數(shù)量和可用性割捅。
參考閱讀
MySQL server has gone away報(bào)錯(cuò)原因分析
django數(shù)據(jù)庫連接
WSGI & uwsgi
