几年前MySQL数据库出现突然的从库延迟故障和CPU爆高时,如何排查具体原因,可能说已在腾讯云的MySQL库里开启了SQL全审计,记录了全部执行的SQL,再通过下面的方法就可以很容易找到原因:
但如果没有开通SQL全审计,如何去找原因。当然说可以看慢SQL日志,但这时的慢SQL日志记录的SQL不全,就不好判断分析出具体是哪些SQL引起的。
如何在非开通SQL全审计的MySQL数据库(因实例不可能都开SQL审计,自建MySQL开还不方便存储查看等),有什么办法? 有更多信息来分析出原因!
当时接手公司数据库运维时,研发已经写了一个Shell,每10秒保存一下当前的:show full processlist ,保留当前执行SQL情况到文件中,后来发现这些还不够,后来加上长事务和表锁,可能更好,Shell脚本如下:
1,CPU爆高:
监控shell:
每10秒执行一次保留当前查询的监控到txt文本中
#!/bin/bash cd $(dirname $0) echo $log_file sql=" show full processlist" ip=172.16.0.15 start_time=$(date +%s) let "check_time=start_time+60"; now=$start_time while [ $now -lt $check_time ]; do log_dir=/root/monitor/$(date +"%Y-%m-%d")/$(date +"%H")/$(date +"%M") mkdir -p $log_dir log_file=$log_dir/$(date +"%Y-%m-%d-%H-%M-%S") echo $sql | mysql -udba_op -ppwd -h$ip mysql > $log_file.master mysql -udba_op -ppwd -h$ip mysql </root/shell/long_tran.sql > $log_file.master_tran echo "next " sleep 10; now=$(date +%s) done
long_tran.sql下的SQL脚本:
select timestampdiff(SECOND,trx_started,now()) diffsecond,b.host,b.user,concat('kill ',b.ID,' ;') killsql,b.db, IFNULL(b.INFO,a.trx_query) runsql from information_schema.innodb_trx a left join information_schema.PROCESSLIST b on a.trx_mysql_thread_id=b.ID where timestampdiff(SECOND,trx_started,now()) >=1 order by 1 desc limit 20; show open tables where in_use >=1;
Crontab运行调度和清理10天前的日志
*/1 * * * * sh /root/shell/sg_monitor_master.sh > /dev/null 2>&1
1 1 * * * find /root/monitor/ -name "20*" -type d -mtime +10 -exec rm -rf {} \; > /dev/null 2>&1
这样每隔10秒就有下面2个文件:
可以结合慢SQL和这2个文件,监控出出问题时当前的数据库的SQL执行情况,找出问题。
2,从库突然延迟
因为当时公司是做在线教育的,但从库延迟几十秒,对他们影响很大,同时领导就会收到报警短信,钉钉群里叫,就要查是什么原因导致的从库延迟,一种方法是查看上面的监控处理的SQL获取信息,另外当时还有解析出binlog信息,查出具体的SQL,看是什么SQL导致的,具体做法:
1,从腾讯云的下载出问题时间的binlog日志本地的机器
2,根据出问题的时间范围,解析binlog日志,如下:
mysqlbinlog --no-defaults -vv --base64-output=decode-rows --start-datetime='2020-08-18 11:20:00' --stop-datetime='2020-08-18 12:03:00' mysql-bin.000203 >log.sql
3,解析出binlog日志后,用notepad++打开文件,仔细查看运行的SQL日志,分析出SQL,这就是细心活。如果查到具体表,可以用上grep过滤,如下:
1, grep user_0 -A 10 -B 10 >/data/61.txt
2, mysqlbinlog --start-datetime="2019-07-08 9:32:00" --stop-datetime="2019-07-09 11:20:00" -v --base64-output=DECODE-ROWS binlog.000001 | grep -A4 'INSERT' > test.sql
4,结合上面信息,发出SQL,让研发同学去修改业务。
注意binlog: 1,主库开启gtid后,pos位置点,每个binlog日志文件开始的pos都是从1开始计算 2,binlog的replace,会转成对应的idelete和insert,或者update等 3,binlog: 执行的SQL都是带有库名 --base64-output参数用来控制binlog部分是否显示出来的,指定为decode-rows表示不显示binglog部分 加-v与加-vv的区别 加-vv ### UPDATE `online`.`ol_teacher_inversion_rate_list` ### WHERE ### @1=595135615 /* INT meta=0 nullable=0 is_null=0 */ 加-v ### UPDATE `online`.`ol_teacher_inversion_rate_list` ### WHERE ### @1=595135615 少一个v,少后面的字段类型信息 加--base64-output=DECODE-ROWS与不加的区别: 加:--base64-output=DECODE-ROWS 不显示原始binlog的二进制信息 :如 BINLOG ' JV7gWg8QJwAAdwAA.......' 4,binlog批量删除 如:DELETE FROM `online`.`ol_task_agents_fixed` WHERE `record_date` = '2021-04-21' 在binlog会一条一条记录,删除5000条,会有5000条delete语句,而且是同一个事务。3,记录原始SQL
当时在公司,公司技术VP说要记录执行的原始SQL,这样大数据读取binlog,把这个原始SQL保留起来,日后审计时就可以通过原始SQL发现谁乱改线上业务数据,同时要把研发人员每次业务要改数据的SQL邮件抄送给他。查询发现mysql还有这样的参数: binlog_rows_query_log_events参数
默认配置下,ROW格式二进制日志只记录数据发生的变化,并不会记录什么语句导致数据发生变化,而出于审计或者处理bug的需求,需要了解导致数据变化的SQL语句,MYSQL提供了binlog_rows_query_log_events来控制是否在二进制中存放"原始SQL"。开启后如下:
后来在主库上开启该参数,大数据就记录主库的SQL执行情况,要监控谁有乱修改更新线上业务数据,但后面一直没用这个数据去查,反而大数据说记录的执行SQL数据量太大,不得不缩短数据保留日期。
标签:binlog,log,10,--,MySQL,分析方法,SQL,日志 From: https://www.cnblogs.com/zping/p/18547692