一次Mysql改表引起LVS下RS機器全下線的問題

時間 2021-03-26

標籤 php mysql nginx web sql 數據庫緩存 app dom php-fpm 欄目 MySQL 简体版

原文原文鏈接

原文連接：http://tabalt.net/blog/mysql-...php

某天下午，正在和code苦戰的我忽然收到報警短信，告警咱們有個業務電信機房LVS下的RS機器所有下線了。第一時間去看機器負載狀況，發現CPU IDLE在80%左右，其餘各項指標也都正常；懷疑是LVS的KeepAlive程序出問題了，上管理平臺點了一遍RS上線，發現服務恢復了，因而未作進一步排查，只向OPS同窗反饋了一下。mysql

然而，剛過了半個小時，一樣的報警又來了，看來還得找到根本緣由。挑了一臺機器保留現場，並在管理平臺將其餘機器操做上線，以保證充分的排查時間。nginx

先檢查Nginx allweb.log中lvscheck相關的日誌，發現狀態碼所有爲499且request_time達到5s：web

[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呢？sql

檢查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同窗。app

DBA同窗排查後發現，當前讀寫量比較大，且有個新增字段的改標語句正在運行，中止後問題恢復；而主從庫QPS的突變是由於從庫延時大被Proxy操做下線了。dom

咱們梳理後發現，當前有個Task程序在批量往數據庫裏導數據，表裏的數據較多（千萬級），這種狀況下改表致使數據庫響應變慢；同時頁面上有個查詢沒有加緩存，SQL語句執行超時設置得也有問題，最終致使PHP-FPM進程都被卡住了，沒有空閒進程來處理LVS健康檢查的頁面，出現了LVS下RS機器全下線的問題。php-fpm

過後，咱們對發現的問題作了修復，並在確保沒有大量訪問的狀況下提交了改表操做，改表順利執行完成。

原文連接：http://tabalt.net/blog/mysql-...