文章详情

短信预约-IT技能 免费直播动态提醒

请输入下面的图形验证码

提交验证

短信预约提醒成功

对MySQL报警的一次分析处理小结

2024-12-03 09:28

关注

最近有一个服务出现了报警,已经让我到了忍无可忍的地步,报警信息如下:

  1. Metric:mysql.innodb_row_lock_waits Tags:port=4306,service=xxxx diff(#1): 996>900 

大概的意思是有一个数据库监控指标innodb_row_lock_waits 目前超出了阈值900

但是尴尬的是,每次报警后去环境中查看,得到的信息都很有限,慢日志,错误日志里面都没有充分的信息可以分析,一来二去之后,我开始静下心来分析这个问题的原因。

首先这个报警信息的时间点貌似是有些规律的,我拿着最近几天的报警时间做了比对,发现还是比较有规律的,那么在系统层面有哪些任务可能会触发呢,我查找比对了相关的任务配置,发现有一个定时任务每1分钟会执行一次,但是到了这里疑问就来了,如果每1分钟执行1次,为什么在特定的时间会产生差异较大的处理结果?当然这个现象的解释是个起始。

其实要证明这一点还是蛮容易的,今天我就采取了守株待兔的模式,我在临近报警的时间前后打开了通用日志,从日志输出来看,操作的频率还是相对有限的。

很快得到了规律性的报警,于是我开始抓取相关的通用日志记录,比如11:18分,我们可以采用如下的模式得到相关的日志,首先得到一个临时的通用日志文件,把各种DML和执行操作都网罗进来。

  1. cat general.log|grep -E "insert|delete|update|select|exec" > general_tmp.log 

我们以11:18分为例,可以在前后1两分钟做比对,结果如下:

  1. # less general_tmp.log |grep "11:18"|wc -l 
  2. 400 
  3. # less general_tmp.log |grep "11:17"|wc -l  
  4. 666 
  5. # less general_tmp.log |grep "11:16"|wc -l  
  6. 15 

发现在报警的那1分钟前后,数量是能够对得上的。

这个表的数据量有200多万,表结构如下:

  1. CREATE TABLE `task_queue` ( 
  2.   `AccID` bigint(20) NOT NULL AUTO_INCREMENT COMMENT '自增ID'
  3.   `TaskStepID` bigint(20) DEFAULT NULL COMMENT '任务步骤ID task_step_conf'
  4.   `QOrder` int(11) DEFAULT NULL COMMENT '队列排序   task_step_confi.Step_ID'
  5.   `QState` tinyint(4) DEFAULT '1' COMMENT '队列状态  1:待执行 2:执行中 3:执行成功 4:执行失败'
  6.   `QExcCount` int(11) DEFAULT '1' COMMENT '执行次数'
  7.   `CrtTime` datetime DEFAULT NULL COMMENT '创建时间'
  8.   `ModTime` datetime DEFAULT NULL COMMENT '修改时间'
  9.   PRIMARY KEY (`AccID`), 
  10.   KEY `idx_taskstepid` (`TaskStepID`), 
  11.   KEY `idx_qstate` (`QState`) 
  12. ) ENGINE=InnoDB AUTO_INCREMENT=3398341 DEFAULT CHARSET=utf8 

在日志中根据分析和比对,基本能够锁定SQL是在一类Update操作上面,SQL的执行计划如下:

  1. >>explain update task_queue set QState=1,QExcCount=QExcCount+1,modtime=now() where QState=0 and taskstepid =411\G 
  2. *************************** 1. row *************************** 
  3.            id: 1 
  4.   select_type: UPDATE 
  5.         table: task_queue 
  6.    partitions: NULL 
  7.          type: index_merge 
  8. possible_keys: idx_taskstepid,idx_qstate 
  9.           key: idx_qstate,idx_taskstepid 
  10.       key_len: 2,9 
  11.           ref: NULL 
  12.          rows: 11 
  13.      filtered: 100.00 
  14.         Extra: Using intersect(idx_qstate,idx_taskstepid); Using where; Using temporary 

这个执行结果中key_len是2,9,是和以往的ken_len计算法则不一样的。 其中Extra列已经给出了明确的提示,这是一个intersect处理,特别的是它是基于二级索引级别的处理,在优化器层面是有一个相关的参数index_merge_intersection。

我们知道在MySQL中主键是一等公民,而二级索引最后都会映射到主键层面处理,而索引级别的intersect其实有点我们的左右手,左手对应一些数据结果映射到一批主键id,右手对应一些数据结果映射到另外一批主键id,把两者的主键id值进行intersect交集计算,所以在当前的场景中,索引级别的intersect到底好不好呢?

在此我设想了3个对比场景进行分析,首先这是一个update语句,我们为了保证后续测试的可重复性,可以转换为一个select语句。

  1. select * from task_queue where QState=0 and taskstepid =411; 

所以我们的对比测试基于查询语句进行比对分析。

场景1:优化器保持默认index_merge_intersection开启,基于profile提取执行明细信息

  1. >explain select * from task_queue where QState=0 and taskstepid =411\G 
  2. *************************** 1. row *************************** 
  3.            id: 1 
  4.   select_type: SIMPLE 
  5.         table: task_queue 
  6.    partitions: NULL 
  7.          type: index_merge 
  8. possible_keys: idx_qstate,idx_taskstepid 
  9.           key: idx_qstate,idx_taskstepid 
  10.       key_len: 2,9 
  11.           ref: NULL 
  12.          rows: 11 
  13.      filtered: 100.00 
  14.         Extra: Using intersect(idx_qstate,idx_taskstepid); Using where 
  15. 1 row in set, 1 warning (0.00 sec) 

profile信息为:

场景2:优化器关闭index_merge_intersection,基于profile进行对比

  1. >set session optimizer_switch='index_merge_intersection=off'
  2.  
  3. >explain select * from task_queue where QState=0 and taskstepid =411\G 
  4. *************************** 1. row *************************** 
  5.            id: 1 
  6.   select_type: SIMPLE 
  7.         table: task_queue 
  8.    partitions: NULL 
  9.          type: ref 
  10. possible_keys: idx_qstate,idx_taskstepid 
  11.           key: idx_qstate 
  12.       key_len: 2 
  13.           ref: const 
  14.          rows: 1451 
  15.      filtered: 0.82 
  16.         Extra: Using where 
  17. 1 row in set, 1 warning (0.00 sec) 

profile信息为:

场景3:重构索引,进行比对分析

根据业务逻辑,如果创建一个复合索引,是能够大大减少结果集的量级的,同时依然保留idx_qstate索引,使得一些业务依然能够正常使用。

  1. >alter table task_queue drop key idx_taskstepid; 
  2. >alter table task_queue add key `idx_taskstepid` (`TaskStepID`,QState); 
  3. explain select * from task_queue where QState=0 and taskstepid =411\G 
  4. *************************** 1. row *************************** 
  5.            id: 1 
  6.   select_type: SIMPLE 
  7.         table: task_queue 
  8.    partitions: NULL 
  9.          type: ref 
  10. possible_keys: idx_qstate,idx_taskstepid 
  11.           key: idx_taskstepid 
  12.       key_len: 11 
  13.           ref: const,const 
  14.          rows: 1 
  15.      filtered: 100.00 
  16.         Extra: NULL 
  17. 1 row in set, 1 warning (0.00 sec) 

profile信息为:

可以明显看到通过索引重构,“Sending data”的部分少了两个数量级

所以接下里的事情就是进一步进行分析和验证,有理有据,等待的过程也不再彷徨,一天过去了,再没有收到1条报警,再次说明在工作中不要小看这些报警。

本文转载自微信公众号「杨建荣的学习笔记」,可以通过以下二维码关注。转载本文请联系杨建荣的学习笔记公众号。

 

 

来源:杨建荣的学习笔记内容投诉

免责声明:

① 本站未注明“稿件来源”的信息均来自网络整理。其文字、图片和音视频稿件的所属权归原作者所有。本站收集整理出于非商业性的教育和科研之目的,并不意味着本站赞同其观点或证实其内容的真实性。仅作为临时的测试数据,供内部测试之用。本站并未授权任何人以任何方式主动获取本站任何信息。

② 本站未注明“稿件来源”的临时测试数据将在测试完成后最终做删除处理。有问题或投稿请发送至: 邮箱/279061341@qq.com QQ/279061341

软考中级精品资料免费领

  • 2024年上半年信息系统项目管理师第二批次真题及答案解析(完整版)

    难度     813人已做
    查看
  • 【考后总结】2024年5月26日信息系统项目管理师第2批次考情分析

    难度     354人已做
    查看
  • 【考后总结】2024年5月25日信息系统项目管理师第1批次考情分析

    难度     318人已做
    查看
  • 2024年上半年软考高项第一、二批次真题考点汇总(完整版)

    难度     435人已做
    查看
  • 2024年上半年系统架构设计师考试综合知识真题

    难度     224人已做
    查看

相关文章

发现更多好内容

猜你喜欢

AI推送时光机
位置:首页-资讯-后端开发
咦!没有更多了?去看看其它编程学习网 内容吧
首页课程
资料下载
问答资讯