开发问MySQL 大事务证据，一个脚本堵上他的嘴

开头还是介绍一下群，如果感兴趣PolarDB ,MongoDB ,MySQL ,PostgreSQL ,Redis, OceanBase, Sql Server等有问题，有需求都可以加群群内有各大数据库行业大咖，可以解决你的问题。加群请联系 liuaustin3 ，（共2400人左右 1 + 2 + 3 + 4 +5 + 6 + 7）(1 2 3 4 5 群均已爆满,6群接近400人即将关闭自由申请，开7群)

MySQL的Binlog是一个经常被提起，且认为功能丰富的日志，实际上BINLOG 负担的任务，有两个第一为数据复制到其他节点，起到了数据传递的功能，第二是数据的操作记录包含了DDL和DML操作等，帮助在数据库出现问题的时候，进行数据的恢复等，很多MYSQL误操作后的恢复就是从Binlog中进行的，同时Binlog在MySQL运行中并不是必须的，

今天咱们咱们就说说Binlog的一些问题和通过一个简单的awk来进行日志的分析的脚本。

问题1：Binlog 选择mix格式，会导致主从的数据不一致吗？

会的,mix是Binlog 采用SBR,RBR混合的方式，在一些情况下选择使用了SBR，statement的方式会导致传递到从库的数据与主库不一致。比如，uuid函数，Now()函数，Rand()等函数，在UPDATE ,INSERT 等语句中使用，这些非确定行的函数如果数据库选择了传递的方式为sbr,那么就有可能导致你的主从数据不一致。

同时如果有自定义函数等，在使用中更是有可能导致数据的主从不一，所以在MySQL的使用中要严格使用 RBR的模式，也就是MySQL官方一直提及的 row模式。

问题2 ：MySQL的并行复制是否会导致业务逻辑错误？

会的， MySQL在后期尤其8.0后最重要的改变之一就是组提交，的并行复制，按照原理在尽显并行的数据复制的情况下，会判定事务之间无关才可以进行并行的数据传输，也就可能导致一种情况，主从库两边的数据在写入到数据库表中的数据的顺序不同，从数据库的角度这是无害的，但从业务逻辑的角度，这是有害的。比如 A 表 和 B表，在数据写入后，A 先写 ，B 后写，且根据A的数值在程序中尽显B 的数值的更新，而如果采用了并行的传输，则可能导致 B 的值先期传入到从库，而应用程序验证B的值是否是A的值更新而来，则会导致应用程序错误，因为B 可能先写入到从库，A的值可能后写入到从库中，这就导致业务逻辑会出现异常。

问题3 ：参数设置错误，导致主从主机某个时刻不一致

在MySQL中，的参数slave_parallel_workers 定义了从库的复制县城并行线程的工作量，默认这个值为0 ,为0说明从库是以串行的方式进行数据的执行，如果将这个值改为其他值后，从库会启动并行复制执行，从库延迟的情况会有好转，但就会引发我们上面说的问题，导致在某一个时间，主从数据不一，业务逻辑有可能错误的情况。同时还有一个参数slave_preserve_commit_order,这个参数控制事务的提交顺序，确保从库在并行执行事务时，保持事务的提交顺序与主库一致，如果将次参数设置为OFF，则会导致我们提到的问题，在某一个时刻，主从数据不一致的情况，或违反业务逻辑的情况出现。同时一定在slave_parallel_type中配置logical_clock，所以在此基础上要注意以上参数的设置，避免出现一些并行复制导致业务逻辑出错的情况。

说完这些问题，我们反过来说说怎么通过Binlog来发现事务操作中的大事务提交的问题，导致的性能问题，一般我们都是依靠监控来看这个问题，但我们如果想从Binlog中找到证据也是可以的，下面我们交给大家一个方法，通过mysqlbinlog 解析日志后，打印每个事务中的操作的行数的大小。

通过这样的awk来预处理BINLOG中的数据，将每个事务中的操作进行计算，且打印出来，方便发现一个事务中是否有一次性大量的插入，删除，或者更新来发现大事务在某个时间段是否发生。

mysqlbinlog --start-datetime="2024-09-20 10:00:00" --stop-datetime="2024-09-20 14:00:00"  --base64-output=decode-rows -vv binlog.001509 | awk 'BEGIN {s_type=""; s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;} {if(match($0, /#15.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1} else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;}  else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;} else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;}  else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; }  else if (match($0, /^(COMMIT)/)) {print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " delete_count "] n+----------------------+----------------------+----------------------+----------------------+"; count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0} } ' > analyze_binlog.001509.log

mysqlbinlog --start-datetime="2024-09-20 10:00:00" --stop-datetime="2024-09-20 14:00:00"  --base64-output=decode-rows -vv binlog.001509 | awk 'BEGIN {s_type=""; s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;} {if(match($0, /#15.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1} else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;}  else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;} else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;}  else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; }  else if (match($0, /^(COMMIT)/)) {print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " delete_count "] n+----------------------+----------------------+----------------------+----------------------+"; count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0} } ' > analyze_binlog.001509.log

下面是类似的程序，但用另一种格式进行输出的

mysqlbinlog --base64-output=decode-rows -vv binlog.001509 | awk '
BEGIN {s_type=""; s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;ddl_count=0;flag=0;ddl_flag=0;ddl_time="";}
{
    if(match($0, /#15.*Table_map:.*mapped to number/)) {
        printf "Timestamp : " $1 " " $2 " Table : " $(NF-4);
        flag=1;
    } 
    else if (match($0, /(### INSERT INTO .*..*)/)) {
        count=count+1;
        insert_count=insert_count+1;
        s_type="INSERT"; 
        s_count=s_count+1;
    }  
    else if (match($0, /(### UPDATE .*..*)/)) {
        count=count+1;
        update_count=update_count+1;
        s_type="UPDATE"; 
        s_count=s_count+1;
    } 
    else if (match($0, /(### DELETE FROM .*..*)/)) {
        count=count+1;
        delete_count=delete_count+1;
        s_type="DELETE";
        s_count=s_count+1;
    }
    else if (match($0, /ALTER TABLE/)) {
        ddl_count=ddl_count+1;
        ddl_flag=1;
    }
    else if (match($0, /^(# at) /) && flag==1 && s_count>0) {
        print " Query Type : "s_type " " s_count " row(s) affected" ;
        s_type="";
        s_count=0;
    }  
    else if (match($0, /^(COMMIT)/)) {
        if (ddl_flag==1) {
            print "[DDL Operation " ddl_count " at time " ddl_time "]";
            ddl_count=0;
            ddl_flag=0;
            ddl_time="";
        }
        print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " delete_count "] n+----------------------+----------------------+----------------------+----------------------+"; 
        count=0;
        insert_count=0;
        update_count=0; 
        delete_count=0;
        s_type="";
        s_count=0;
        flag=0;
    }
    else if (ddl_flag==1 && match($0, /# at/)) {
        split($1, time_part, ":");
        ddl_time = time_part[1] ":" time_part[2] ":" time_part[3];
    }
}
'  > test.log