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