[[388536]] 最近有一个服务出现了报警，对M的次已经让我到了忍无可忍的分析地步，报警信息如下： 复制Metric:mysql.innodb_row_lock_waits Tags:port=4306,处理service=xxxx diff(#1): 996>900 1. 大概的意思是有一个数据库监控指标innodb_row_lock_waits 目前超出了阈值900 但是尴尬的是，每次报警后去环境中查看，小结得到的对M的次信息都很有限，慢日志，分析错误日志里面都没有充分的处理信息可以分析，一来二去之后，小结我开始静下心来分析这个问题的对M的次原因。 首先这个报警信息的分析时间点貌似是有些规律的，我拿着最近几天的处理报警时间做了比对，发现还是云服务器小结比较有规律的，那么在系统层面有哪些任务可能会触发呢，对M的次我查找比对了相关的分析任务配置，发现有一个定时任务每1分钟会执行一次，处理但是到了这里疑问就来了，如果每1分钟执行1次，为什么在特定的时间会产生差异较大的处理结果?当然这个现象的解释是个起始。 
其实要证明这一点还是蛮容易的，今天我就采取了守株待兔的模式，我在临近报警的时间前后打开了通用日志，从日志输出来看，操作的频率还是相对有限的。亿华云 很快得到了规律性的报警，于是我开始抓取相关的通用日志记录，比如11:18分，我们可以采用如下的模式得到相关的日志，首先得到一个临时的通用日志文件，把各种DML和执行操作都网罗进来。 复制cat general.log|grep -E "insert|delete|update|select|exec" > general_tmp.log 1. 我们以11:18分为例，可以在前后1两分钟做比对，结果如下： 复制# less general_tmp.log |grep "11:18"|wc -l 400 # less general_tmp.log |grep "11:17"|wc -l 666 # less general_tmp.log |grep "11:16"|wc -l 15 1.2.3.4.5.6. 发现在报警的那1分钟前后，数量是能够对得上的。 这个表的数据量有200多万，表结构如下： 复制CREATETABLE `task_queue` ( `AccID` bigint(20) NOTNULL AUTO_INCREMENT COMMENT 自增ID, `TaskStepID` bigint(20) DEFAULTNULL COMMENT 任务步骤ID task_step_conf, `QOrder` int(11) DEFAULTNULL COMMENT 队列排序 task_step_confi.Step_ID, `QState` tinyint(4) DEFAULT1 COMMENT 队列状态 1：待执行 2：执行中 3：执行成功 4：执行失败, `QExcCount` int(11) DEFAULT1 COMMENT 执行次数, `CrtTime` datetime DEFAULTNULL COMMENT 创建时间, `ModTime` datetime DEFAULTNULL COMMENT 修改时间, PRIMARYKEY (`AccID`), KEY `idx_taskstepid` (`TaskStepID`), KEY `idx_qstate` (`QState`) ) ENGINE=InnoDB AUTO_INCREMENT=3398341 DEFAULT CHARSET=utf8 1.2.3.4.5.6.7.8.9.10.11.12. 在日志中根据分析和比对，基本能够锁定SQL是在一类Update操作上面，SQL的执行计划如下： 复制>>explain update task_queue set QState=1,QExcCount=QExcCount+1,modtime=now() where QState=0 and taskstepid =411\G |
喜欢
讨厌