一次Mysql改表引發(fā)LVS下RS機器全下線的問題
某天下午，正在和code苦戰(zhàn)的我突然收到報警短信，告警我們有個業(yè)務(wù)電信機房LVS下的RS機器全部下線了。***時間去看機器負(fù)載情況，發(fā)現(xiàn)CPU IDLE在80%左右，其他各項指標(biāo)也都正常;懷疑是LVS的KeepAlive程序出問題了，上管理平臺點了一遍RS上線，發(fā)現(xiàn)服務(wù)恢復(fù)了，于是未做進一步排查，只向OPS同學(xué)反饋了一下。
然而，剛過了半個小時，同樣的報警又來了，看來還得找到根本原因。挑了一臺機器保留現(xiàn)場，并在管理平臺將其他機器操作上線，以保證充分的排查時間。
先檢查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程序請求http://lvscheck.domain.com/status.php頁面探測服務(wù)情況時，竟然過了5s都沒有收到響應(yīng)，于是主動斷開請求并將RS下線了。但機器很閑，為什么/status.php會處理超過5s呢?
檢查PHP-FPM的日志，發(fā)現(xiàn)有報錯/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只是入口文件，從這個日志看不出來問題在哪里，再檢查下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的時候很慢，上管理平臺查看發(fā)現(xiàn)在報警的兩個時間點，MySQL從庫的QPS突然降到0而主庫QPS突然大幅升高，于是連忙反饋給DBA同學(xué)。
DBA同學(xué)排查后發(fā)現(xiàn)，當(dāng)前讀寫量比較大，且有個新增字段的改標(biāo)語句正在運行，停止后問題恢復(fù);而主從庫QPS的突變是因為從庫延時大被Proxy操作下線了。
我們梳理后發(fā)現(xiàn)，當(dāng)前有個Task程序在批量往數(shù)據(jù)庫里導(dǎo)數(shù)據(jù)，表里的數(shù)據(jù)較多(***)，這種情況下改表導(dǎo)致數(shù)據(jù)庫響應(yīng)變慢;同時頁面上有個查詢沒有加緩存，SQL語句執(zhí)行超時設(shè)置得也有問題，最終導(dǎo)致PHP-FPM進程都被卡住了，沒有空閑進程來處理LVS健康檢查的頁面，出現(xiàn)了LVS下RS機器全下線的問題。
事后，我們對發(fā)現(xiàn)的問題做了修復(fù)，并在確保沒有大量訪問的情況下提交了改表操作，改表順利執(zhí)行完成。
