Resolution of MySQL deadlock log from errorlog based on innodb_print_all_deadlocks

Keywords: MySQL Database

This article explains how to get deadlock log records, not how to solve the deadlock problem.


MySQL deadlocks can be viewed through show engine innodb status.
But show engine innodb status; can only display the latest deadlock, this way can not fully capture the deadlock information occurring in the system.
If you want to record all deadlock logs, open the innodb_print_all_deadlocks parameter to record all deadlock logs in errorlog.
So the problem becomes how to parse deadlock logs from errorlog.

Referring to the screenshot below, this is a typical deadlock log information in errorlog. In addition to the deadlock log, it can create some other interference logs (deliberately log in to the database without entering a password so that it can record some other error log information).
If you want to parse this deadlock log (excluding other unrelated logs), that is, parse the generated deadlock content and split two (or more) transactions in the content of the deadlock log.
1. The marker for the start and end of a deadlock====> intercepts the contents of a single deadlock log
2. Resolve the deadlock log in Step 1===> Intercept transaction logs

The following parsing is based on the following rules, basically matching based on keywords and rules
1. Mark at the beginning of deadlock log: Transactions deadlock detection, dumping detailed information.
2. Marking the beginning of a deadlock day transaction: *** (N) TRANSACTION:
3. Marking the end of deadlock: 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 log table structure. A complete deadlock is split according to the start time of the first transaction in consideration. If deadlock_id is the same, it means that it belongs to a deadlock.
        create table deadlock_log
        (
            id int auto_increment primary key,
            deadlock_id varchar(50),
            deadlock_transaction_content text,
            create_date datetime
        ) 
       '''
        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")

    #Resolving deadlock log content
    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):#Contain deadlock String representing the start of deadlock log
                                #Output deadlock log,Mark deadlock log start
                                deadlock_content = deadlock_content+line
                                deadlock_flag = 1
                    elif(deadlock_flag == 1):
                        #Output deadlock log
                        deadlock_content = deadlock_content + line
                        #Deadlock Log End
                        if (line.find("ROLL BACK")>0):#Contain roll back String, indicating the end of deadlock log
                            deadlock_flag = 0
                            #End of parsing of a complete deadlock log
                            deadlock_set.add(deadlock_content)
                            deadlock_content = ""
        except IOError as err:
            raise (IOError, "read file error")
        return deadlock_set



    #Resolving transaction information in deadlock log
    def analysis_mysqlerrorlog(self,deadlock_set):
        #Single transaction start tag
        transaction_begin_flag = 0
        #Single transaction information in deadlock
        transaction_content = ""
        # Deadlock occurrence time
        str_datetime = ""
        #Matching transaction start tag rule
        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", " "))):
                    #Deadlock occurrence time. When parsing the contents of the deadlock log, each group of deadlock logs is assigned only once, and everything in a deadlock takes the first time.
                    str_datetime = line[0:19].replace("T", " ")
                #Transaction Start Marker in Deadlock Log
                if( pattern.search(line)):
                    transaction_begin_flag = 1
                    #Transaction begins, and the last transaction content is written to the database
                    if(transaction_content):
                        self.insert_deadlock_content(str_datetime,transaction_content)
                        #Start a new transaction in the deadlock log, reset transaction_content And transaction start Tags
                        transaction_content = ""
                        ransaction_begin_flag = 0
                else:
                    #Specific logs for deadlocks generated by a transaction
                    if(transaction_begin_flag==1):
                        transaction_content = transaction_content +"\n"+ line
            #Last transaction information in deadlock log
            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)

 

Following is the transaction information corresponding to a set of deadlocks whose id is 1,2 and whose id is 3,4.

 

Some of my ideas are just quick common sense, but there are still many shortcomings.
1. The parsed log format is very rough
2. All the deadlocks parsed are regular ones. We are not sure that we can hold all the deadlock log formats. If we parse them according to keywords, we don't know if we will always be ready.
3. How to avoid repetitive parsing, that is, when parsing error s of MySQL regularly, without judging what was parsed the previous time?
4. No efficiency test.

Posted by Arenlor on Sat, 05 Jan 2019 13:36:09 -0800