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

Posted 2020-12-02 专注，勤学，慎思。戒骄戒躁，谦虚谨慎

 

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

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，没有做效率测试