一次Mysql改表引發(fā)LVS下RS機(jī)器全下線的問題
某天下午，正在和code苦戰(zhàn)的我突然收到報(bào)警短信，告警我們有個(gè)業(yè)務(wù)電信機(jī)房LVS下的RS機(jī)器全部下線了。***時(shí)間去看機(jī)器負(fù)載情況，發(fā)現(xiàn)CPU IDLE在80%左右，其他各項(xiàng)指標(biāo)也都正常;懷疑是LVS的KeepAlive程序出問題了，上管理平臺(tái)點(diǎn)了一遍RS上線，發(fā)現(xiàn)服務(wù)恢復(fù)了，于是未做進(jìn)一步排查，只向OPS同學(xué)反饋了一下。
然而，剛過了半個(gè)小時(shí)，同樣的報(bào)警又來了，看來還得找到根本原因。挑了一臺(tái)機(jī)器保留現(xiàn)場，并在管理平臺(tái)將其他機(jī)器操作上線，以保證充分的排查時(shí)間。
先檢查Nginx allweb.log中l(wèi)vscheck相關(guān)的日志，發(fā)現(xiàn)狀態(tài)碼全部為499且request_time達(dá)到5s：
- [tabalt@server01 ~]$ tail -100 /data/nginx/logs/allweb.log | grep lvscheck
- 10.18.42.2 92 0 5.000[s] - - [12/Jul/2017:18:29:18 +0800] "GET /status.php HTTP/1.0" 499 - "-" "KeepAliveClient" lvscheck.domain.com 10.20.12.60 - -
- 10.18.42.2 92 0 5.000[s] - - [12/Jul/2017:18:29:22 +0800] "GET /status.php HTTP/1.0" 499 - "-" "KeepAliveClient" lvscheck.domain.com 10.20.12.60 - -
- 10.18.42.2 92 0 5.000[s] - - [12/Jul/2017:18:29:24 +0800] "GET /status.php HTTP/1.0" 499 - "-" "KeepAliveClient" lvscheck.domain.com 10.20.12.60 - -
- ...
原來KeepAlive程序請(qǐng)求http://lvscheck.domain.com/status.php頁面探測(cè)服務(wù)情況時(shí)，竟然過了5s都沒有收到響應(yīng)，于是主動(dòng)斷開請(qǐng)求并將RS下線了。但機(jī)器很閑，為什么/status.php會(huì)處理超過5s呢?
檢查PHP-FPM的日志，發(fā)現(xiàn)有報(bào)錯(cuò)/data/www/front/index.php文件執(zhí)行很慢：
- [tabalt@server01 ~]$ tail /data/php/log/php-fpm.log
- 12-Jul-2017 18:29:18] WARNING: [pool www] child 3988, script '/data/www/front/index.php' (request: "GET /index.php") executing too slow (11.301960 sec), logging
- [12-Jul-2017 18:29:22] WARNING: [pool www] child 3945, script '/data/www/front/index.php' (request: "GET /index.php") executing too slow (11.863325 sec), logging
- [12-Jul-2017 18:29:24] WARNING: [pool www] child 3887, script '/data/www/front/index.php' (request: "GET /index.php") executing too slow (10.498795 sec), logging
- ...
但/data/www/front/index.php只是入口文件，從這個(gè)日志看不出來問題在哪里，再檢查下PHP-FPM的慢日志：
- [tabalt@server01 ~]$ tail -100 /data/php/log/www.log.slow
- ...
- script_filename = /data/www/front/index.php
- [0x00007fecbd613f90] execute() /data/www/vendor/andals/vine/src/Component/Mysql/Driver.php:218
- [0x00007fecbd613ec0] doExecute() /data/www/vendor/andals/vine/src/Component/Mysql/Driver.php:66
- [0x00007fecbd613df0] query() /data/www/vendor/andals/vine/src/Component/Mysql/Dao/Base.php:206
- [0x00007fecbd613d80] simpleQuery() /data/www/src/app/Model/Dao/Base.php:65
- [0x00007fecbd613cc0] selectByParamsForFront() /data/www/src/app/Model/Svc/SqlBase.php:211
- [0x00007fecbd613c10] selectByParamsForFront() /data/www/src/app/Model/Svc/Category.php:214
- ...
- [0x00007fecbd613580] getEsData() /data/www/src/app/Controller/Front/ListController.php:26
- [0x00007fecbd613400] indexAction() /data/www/vendor/andals/vine/src/Framework/App/Web.php:107
- [0x00007fecbd613380] call_user_func_array() /data/www/vendor/andals/vine/src/Framework/App/Web.php:107
- [0x00007fecbd613290] runController() /data/www/vendor/andals/vine/src/Framework/App/Web.php:73
- [0x00007fecbd6131b0] handleRequest() /data/www/vendor/andals/vine/src/Framework/App/Web.php:48
- [0x00007fecbd6130f0] run() /data/www/src/run/front/index.php:6
可以看到最終是執(zhí)行SQL的時(shí)候很慢，上管理平臺(tái)查看發(fā)現(xiàn)在報(bào)警的兩個(gè)時(shí)間點(diǎn)，MySQL從庫的QPS突然降到0而主庫QPS突然大幅升高，于是連忙反饋給DBA同學(xué)。
DBA同學(xué)排查后發(fā)現(xiàn)，當(dāng)前讀寫量比較大，且有個(gè)新增字段的改標(biāo)語句正在運(yùn)行，停止后問題恢復(fù);而主從庫QPS的突變是因?yàn)閺膸煅訒r(shí)大被Proxy操作下線了。
我們梳理后發(fā)現(xiàn)，當(dāng)前有個(gè)Task程序在批量往數(shù)據(jù)庫里導(dǎo)數(shù)據(jù)，表里的數(shù)據(jù)較多(***)，這種情況下改表導(dǎo)致數(shù)據(jù)庫響應(yīng)變慢;同時(shí)頁面上有個(gè)查詢沒有加緩存，SQL語句執(zhí)行超時(shí)設(shè)置得也有問題，最終導(dǎo)致PHP-FPM進(jìn)程都被卡住了，沒有空閑進(jìn)程來處理LVS健康檢查的頁面，出現(xiàn)了LVS下RS機(jī)器全下線的問題。
事后，我們對(duì)發(fā)現(xiàn)的問題做了修復(fù)，并在確保沒有大量訪問的情況下提交了改表操作，改表順利執(zhí)行完成。
