基于innodb_print_all_deadlocks从errorlog中解析MySQL死锁日志

服务器

浏览数:142

2019-7-8

AD:资源代下载服务

本文是说明如何获取死锁日志记录的,不是说明如何解决死锁问题的。

MySQL的死锁可以通过show engine innodb status;来查看,
但是show engine innodb status;只能显示最新的一条死锁,该方式无法完全捕获到系统发生的死锁信息。
如果想要记录所有的死锁日志,打开innodb_print_all_deadlocks参数可以将所有的死锁日志记录到errorlog中,
因此问题就变成了如何从errorlog解析死锁日志。

参考如下截图,是errorlog中的一个典型的死锁日志信息,除了死锁日志,可以制造了一些其他的干扰日志(故意不输入密码登陆数据库让它记录一些其他错误日志信息)
如果要解析这个死锁日志(排除其他无关日志),也即解析产生死锁内容,拆分死锁日志内容中的两个(或者)多个事务
1,死锁开始和结束的标记====>截取单个死锁日志内容
2,解析第1步中的死锁日志===>截取各个事务日志

以下解析基于如下规则,基本上都是根据本关键字和正则做匹配
1,死锁日志开始的标记: Transactions deadlock detected, dumping detailed information.
2,死锁日中中事务开始的标记:*** (N) TRANSACTION:
3,死锁结束的标记:WE ROLL BACK TRANSACTION (N)

import os
import time
import datetime
import re
from IO.mysql_operation import mysql_operation


class mysql_deadlock_analysis:

    def __init__(self):
        pass


    def is_valid_date(self,strdate):
        try:
            if ":" in strdate:
                time.strptime(strdate, "%Y-%m-%d %H:%M:%S")
            else:
                time.strptime(strdate, "%Y-%m-%d")
            return True
        except:
            return False

    def insert_deadlock_content(self,str_id, str_content):
        connstr = {'host': '***,***,***,***',
                   'port': 3306,
                   'user': 'username',
                   'password': 'pwd',
                   'db': 'db01',
                   'charset': 'utf8mb4'}
        mysqlconn = mysql_operation(host=connstr['host'],
                                    port=connstr['port'],
                                    user=connstr['user'],
                                    password=connstr['password'],
                                    db=connstr['db'],
                                    charset=connstr['charset'])
        '''
        死锁日志表结构,一个完整的死锁日志按照死锁中第一个事务开始时间为主,deadlock_id一样的话,说明是归属于一个死锁
        create table deadlock_log
        (
            id int auto_increment primary key,
            deadlock_id varchar(50),
            deadlock_transaction_content text,
            create_date datetime
        ) 
       '''
    str_content = str_content.replace("'","''")
    str_sql = "insert into deadlock_log(deadlock_id,deadlock_transaction_content,create_date) " \
                  "values ('%s','%s',now())" % (str_id, str_content)
        try:
            mysqlconn.execute_noquery(str_sql, None)
        except  Exception as err:
            raise (Exception, "database operation error")

    #解析死锁日志内容
    def read_mysqlerrorlog(self,file_name):
        try:
            deadlock_flag = 0
            deadlock_set = set()
            deadlock_content = ""
            with open(file_name,"r") as f:
                for line in f:
                    if(deadlock_flag == 0):
                        str_datetime = line[0:19].replace("T"," ")
                        if(self.is_valid_date(str_datetime)):
                            if(line.find("deadlock")>0):#包含deadlock字符串,表示死锁日志开始
                                #输出死锁日志,标记死锁日志开始
                                deadlock_content = deadlock_content+line
                                deadlock_flag = 1
                    elif(deadlock_flag == 1):
                        #输出死锁日志
                        deadlock_content = deadlock_content + line
                        #死锁日志结束
                        if (line.find("ROLL BACK")>0):#包含roll back 字符串,表示死锁日志结束
                            deadlock_flag = 0
                            #一个完整死锁日志的解析结束
                            deadlock_set.add(deadlock_content)
                            deadlock_content = ""
        except IOError as err:
            raise (IOError, "read file error")
        return deadlock_set



    #解析死锁日志中的各个事务信息
    def analysis_mysqlerrorlog(self,deadlock_set):
        #单个事务开始标记
        transaction_begin_flag = 0
        #死锁中的单个事务信息
        transaction_content = ""
        # 死锁发生时间
        str_datetime = ""
        #匹配事务开始标记正则
        pattern = re.compile(r'[*]* [(0-9)]* TRANSACTION:')
        for str_content in deadlock_set:
            arr_content = str_content.split("\n")
            for line in arr_content:
                if (self.is_valid_date(line[0:19].replace("T", " "))):
                    #死锁发生时间,在解析死锁日志内容的时候,每组死锁日志只赋值一次,一个死锁中的所有事物都用第一次的时间
                    str_datetime = line[0:19].replace("T", " ")
                #死锁日志中的事务开始标记
                if( pattern.search(line)):
                    transaction_begin_flag = 1
                    #事务开始,将上一个事务内容写入数据库
                    if(transaction_content):
                        self.insert_deadlock_content(str_datetime,transaction_content)
                        #死锁日志中新开始一个事务,重置transaction_content以及事务开始标记
                        transaction_content = ""
                        transaction_begin_flag = 0
                else:
                    #某一个事务产生死锁的具体日志
                    if(transaction_begin_flag==1):
                        transaction_content = transaction_content +"\n"+ line
            #死锁日志中的最后一个事务信息
            if (transaction_content):
                self.insert_deadlock_content(str_datetime, transaction_content)
                transaction_content = ""
                transaction_begin_flag = 0


if __name__ == '__main__':
    file_path = "\path\mysql.err"
    analysis = mysql_deadlock_analysis()
    str_content = analysis.read_mysqlerrorlog(file_path)
    analysis.analysis_mysqlerrorlog(str_content)

以下是写入到数据库之后的效果id为1,2的对应一组死锁的事务信息,id为3,4的对应一组死锁事务

 

纯属快速尝试自己的一些个想法,还有很多不足
1,解析后的日志格式很粗
2,解析的都是常规的死锁,不确定能hold所有的死锁日志格式,根据关键字解析的,不知道是不是总是有效
3,如何避免重复解析,也即定时解析MySQL的error的时候,没判断前一次解析过的内容的判断
4,没有做效率测试

 

作者:MSSQL123