mysql sys库 oom_MySQL异常OOM排查

收到告警，提示mysql挂了，此时看监控，负载已经比较高，服务器已经无法登录。看见监控此时的负载情况如下：

除了系统层面的监控还可以看到，mysql层面的监控已经断图，等负载降下来的时候mysql已经被oom，自动重启了。

从mysql错误日志看到如下信息：

2020-08-01T09:14:11.778918+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4271ms. The settings might not be optimal. (flushed=386 and evicted=119, during the time.)

这基本上说明，数据库收到的写入过多，导致BufferPool充满脏页。这会触发PageCleaner进行操作并清除脏页。由于脏页比平时多，因此PageCleaner清除缓冲区需要花费更多时间。

由于监控在负载异常高的这段时间msyql层面已经断图，看不到相关监控，那么如何排查呢？那只能从binlog入手了，好，那么分析一下binlog，看有没有大事务之类的。

mysqlbinlog mysql-bin.005298 | grep "GTID$(printf 't')last_committed" -B 1 | egrep -E '^# at|^#20' | awk '{print $1,$2,$3}' | sed 's/server//' | sed 'N;s/n/ /' | awk 'NR==1 {tmp=$1} NR>1 {print $4,$NF,($3-tmp);tmp=$3}' | sort -k 3 -n -r | head -n 20

可以看见再8:56:44左右，可以看见最大的一个事务在100M，这是比较大了。通过在该时间范围内继续解析binlog，发现有大范围的更新数据。这不够直观，我们写一段代码，把DML趋势放入ES来分析一下，代码比较简单，如下：

#!/usr/bin/python#coding: utf8

"""跟踪一段时间内dml趋势，用ES分析

Usage:

python dml2es.py | logstash -f /etc/logstash/conf.d/t_binlog.conf"""

importjsonimportosimportsysimportloggingfrom datetime importdatetimefrom pymysqlreplication importBinLogStreamReaderfrom pymysqlreplication.event importQueryEvent, RotateEventfrom pymysqlreplication.row_event import(

WriteRowsEvent,

UpdateRowsEvent,

DeleteRowsEvent,

)definit_log():#get root logger

mylogger =logging.getLogger()

mylogger.setLevel(logging.DEBUG)#create file handler and add formatter to handler

verbose_log_file = "/tmp/%s.verbose.log" %(os.path.basename(sys.argv[0]))

fh=logging.FileHandler(verbose_log_file)

fh.setLevel(logging.DEBUG)

fh.setFormatter(logging.Formatter(

fmt="%(asctime)s %(filename)s:%(lineno)d %(levelname)s %(message)s",

datefmt="%a %d %b %Y %H:%M:%S"))#create stream handler and add formatter to handler

sh =logging.StreamHandler(sys.stdout)

sh.setLevel(logging.INFO)

sh.setFormatter(logging.Formatter(

fmt="%(asctime)s %(levelname)-8s %(message)s",

datefmt="%H:%M:%S"))#add two handler to logger

mylogger.addHandler(fh)

mylogger.addHandler(sh)returnmyloggerif __name__ == "__main__":

logger=init_log()

mysql_settings={'host': '127.0.0.1','port': 3306,'user': 'xxx','passwd': 'xxx'}

binlog_file= 'mysql-bin.005298'start_position= 123stop_position= 1031510925

#不需要blocking

stream =BinLogStreamReader(

connection_settings=mysql_settings,

server_id=9999,

log_file=binlog_file,

log_pos=start_position,

resume_stream=True,

blocking=False

)for binlogevent instream:

data={}if binlogevent.packet.log_pos >=stop_position:break

#当输出 "@timestamp" : binlogevent.timestamp

#即 "@timestamp" => 1582624830

#logstash 会有warning

#[WARN ] 2020-02-25 18:00:31.313 [[main]

#所以需要进行下面的格式转换

#使用 datetime.fromtimestamp 将解析为 当前操作系统时区的 datetime

ifisinstance(binlogevent, WriteRowsEvent):

data={"schema": binlogevent.schema,"table": binlogevent.table,"dmltype" : "insert","@timestamp" :datetime.fromtimestamp(binlogevent.timestamp).strftime('%Y-%m-%dT%H:%M:%S') ,

}printjson.dumps(data)elifisinstance(binlogevent, DeleteRowsEvent):

data={"schema": binlogevent.schema,"table": binlogevent.table,"dmltype" : "delete","@timestamp" :datetime.fromtimestamp(binlogevent.timestamp).strftime('%Y-%m-%dT%H:%M:%S') ,

}printjson.dumps(data)elifisinstance(binlogevent, UpdateRowsEvent):

data={"schema": binlogevent.schema,"table": binlogevent.table,"dmltype" : "update","@timestamp" :datetime.fromtimestamp(binlogevent.timestamp).strftime('%Y-%m-%dT%H:%M:%S') ,

}printjson.dumps(data)elifisinstance(binlogevent, RotateEvent):if binlogevent.packet.log_pos <= 1655:

logger.debug( u"next_binlog:" +binlogevent.next_binlog )

stream.close()

View Code

我们在kibana里面把时间缩短到秒级看看这段时间的DML趋势

可以看见和我们直接分析binlog得到的结果一致，就是这个时间点的几个大事务导致的大量的数据更新。由于innodb_page_cleaners参数已经是4，不做调整。

总结：

1.杜绝大事务，同时注意SQL是否合理利用索引

2.mysql相关参数调整，比如innodb_io_capacity，innodb_io_capacity_max，由于这台机器使用的NVME接口的SSD，故把innodb_io_capacity参数调整到10000