最近有一个服务告警，搞得我受不了。告警信息如下：metric:mysql.innodb_row_lock_waitsTags:port=4306,service=xxxxdiff(#1):996>900大致意思是有一个数据库监控指标innodb_row_lock_waits当前超过900的阈值，但是尴尬的事情就是每次在环境中查看告警，获取到的信息都非常有限，慢日志和错误日志中都没有足够的信息。分析，一来二去，我开始静下心来分析这个问题的原因。首先，报警信息的时间点似乎有些规律。对比了最近几天的闹钟时间，发现还是挺有规律的。那么在系统层面可能会触发哪些任务呢？我搜索比较了一下相关的任务配置，发现有一个定时任务会每隔1分钟执行一次，但是问题就出现在这里了。如果每1分钟执行一次，为什么在特定时间会产生不同的处理结果？当然这现象的解释是开始。事实上，要证明这一点是相当容易的。今天我采用了等兔子的模式。我在警报时间前后打开了一般日志。从日志输出来看，操作频率比较有限。很快就得到了规律的告警，于是开始抓取相关的通用日志记录，比如11点18分，我们可以使用如下方式获取相关日志，先获取一个临时的通用日志文件，放各种DML和执行操作包括。catgeneral.log|grep-E"insert|delete|update|select|exec">general_tmp.log以11点18分为例，可以做前后1、2分钟的对比。结果如下：#lessgeneral_tmp.log|grep"11:18"|wc-l400#lessgeneral_tmp.log|grep"11:17"|wc-l666#lessgeneral_tmp.log|grep"11:16"|wc-l15发现报警前后，号码是能够匹配的。该表数据量超过200万，表结构如下：CREATETABLE`task_queue`(`AccID`bigint(20)NOTNULLAUTO_INCREMENTCOMMENT'自增ID',`TaskStepID`bigint(20)DEFAULTNULLCOMMENT'taskstepIDtask_step_conf',`QOrder`int(11)DEFAULTNULLCOMMENT'队列排序task_step_confi.Step_ID',`QState`tinyint(4)DEFAULT'1'COMMENT'队列状态1：待执行2：正在执行3：执行成功4：执行失败',`QExcCount`int(11)DEFAULT'1'COMMENT'执行次数',`CrtTime`datetimeDEFAULTNULLCOMMENT'创建时间',`ModTime`datetimeDEFAULTNULLCOMMENT'修改时间',PRIMARYKEY(`AccID`),KEY`idx_taskstepid`(`TaskStepID`),KEY`idx_qstate`(`QState`))ENGINE=InnoDBAUTO_INCREMENT=3398341DEFAULTCHARSET=utf8根据日志中的分析对比，SQL基本可以锁定在一类Update操作上。SQL执行计划如下：>>explainupdatetask_queuesetQState=1,QExcCount=QExcCount+1,modtime=now()whereQState=0andtaskstepid=411\G**************************1.row***************************id:1select_type:UPDATEtable:task_queuepartitions:NULLtype:index_mergepossible_keys:idx_taskstepid，idx_qstatekey：idx_qstate，idx_taskstepidkey_len：2,9ref：NULLrows：11filtered：100.00Extra：使用相交(idx_qstate,idx_taskstepid);Usingwhere;Usingtemporary执行结果中key_len为2,9，与之前的ken_len计算规则不同。Extra专栏已经给出了明确的提示。这是一个intersect过程，特别是它是基于secondaryindex层面的处理，在optimizer层面有一个相关的参数index_merge_intersection。我们知道在MySQL中，主键是一等公民，二级索引最终会映射到主键层面进行处理，而索引层面的交集其实就是我们的左右手。左手对应一些数据结果映射到一批主键id，右手对应一些数据。将结果映射到另一批主键id，对两者的主键id值进行交集计算，那么在当前场景下，索引级交集好不好？这里我想象了3个对比场景进行分析。首先这是一个更新语句。为了保证后续测试的可重复性，我们可以将其转化为select语句。select*fromtask_queuewhereQState=0andtaskstepid=411;所以我们的对比测试是基于查询语句进行对比分析。场景一：优化器保持默认的index_merge_intersection开启，并根据profile提取执行细节>explainselect*fromtask_queuewhereQState=0andtaskstepid=411\G******************************1.row***************************id:1select_type:SIMPLEtable:task_queuepartitions:NULLtype:index_mergepossible_keys:idx_qstate,idx_taskstepidkey:idx_qstate,idx_taskstepidkey_len:2,9ref:NULLrows:11filtered:100.00Extra:Usingintersect(idx_qstate,idx_taskstepid);Usingwhere1rowinset,1warning(0.00sec)profile信息为：场景二：优化器禁用index_merge_intersection，根据profile进行比较>setsessionoptimizer_switch_switch=off';>解释选择*fromtask_queuewhereQState=0andtaskstepid=411\G*********************************1.row***************************id:1select_type:SIMPLEtable:task_queuepartitions:NULLtype:refpossible_keys:idx_qstate,idx_taskstepidkey:idx_qstatekey_len:2ref:constrows:1451filtered:0.82Extra:Usingwhere1rowinset,1warning(0.00sec)T概况信息为：场景三：重构索引并进行对比分析根据业务逻辑，如果创建复合索引，可以大大降低结果集的量级，同时仍然保留idx_qstate索引，这样部分业务仍可正常使用>altertabletask_queuedropkeyidx_taskstepid;>altertabletask_queueaddkey`idx_taskstepid`(`TaskStepID`,QState);解释选择*fromtask_queuewhereQState=0andtaskstepid=411\G***************************1.row******************************id:1select_type:SIMPLEtable:task_queuepartitions:NULLtype:refpossible_keys:idx_qstate,idx_taskstepidkey:idx_taskstepidkey_len:11ref:const,constrows:1filtered:100.00Extra:NULL1rowinset,1warning(0.00sec)profile信息为：通过索引重构可以清楚的看到“Sendingdata”部分少了两个数量级接下来要做的是进一步分析验证。有理有据，等待的过程也不再犹豫。一天过去了，再也没有收到报警。再次重申，不要低估这些警报的作用。本文转载自微信公众号《杨建荣的学习笔记》，可通过以下二维码关注。转载本文请联系杨建荣学习笔记公众号。
