一次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-...