MySQL無開通SQL全審計下的故障分析方法

zping發表於2024-11-18
MySql

幾年前MySQL資料庫出現突然的從庫延遲故障和CPU爆高時，如何排查具體原因，可能說已在騰訊雲的MySQL庫裡開啟了SQL全審計，記錄了全部執行的SQL，再透過下面的方法就可以很容易找到原因：

1，實用QPS和TPS高的高效分析方法

但如果沒有開通SQL全審計，如何去找原因。當然說可以看慢SQL日誌，但這時的慢SQL日誌記錄的SQL不全，就不好判斷分析出具體是哪些SQL引起的。

如何在非開通SQL全審計的MySQL資料庫（因例項不可能都開SQL審計，自建MySQL開還不方便儲存檢視等），有什麼辦法? 有更多資訊來分析出原因！

當時接手公司資料庫運維時，研發已經寫了一個Shell，每10秒儲存一下當前的：show full processlist ，保留當前執行SQL情況到檔案中，後來發現這些還不夠，後來加上長事務和表鎖，可能更好，Shell指令碼如下：

1，CPU爆高：

監控shell：

每10秒執行一次保留當前查詢的監控到txt文字中

#!/bin/bash
cd $(dirname $0)
echo $log_file
sql=" show full processlist"
ip=172.16.0.15

start_time=$(date +%s)
let "check_time=start_time+60";
now=$start_time
while [ $now -lt  $check_time  ];
do
    log_dir=/root/monitor/$(date +"%Y-%m-%d")/$(date +"%H")/$(date +"%M")
    mkdir -p $log_dir    
    log_file=$log_dir/$(date +"%Y-%m-%d-%H-%M-%S")
    echo $sql | mysql   -udba_op -ppwd -h$ip mysql  > $log_file.master
        mysql   -udba_op -ppwd -h$ip mysql </root/shell/long_tran.sql > $log_file.master_tran
    echo "next "
    sleep 10;
    now=$(date +%s)
done

long_tran.sql下的SQL指令碼：

select timestampdiff(SECOND,trx_started,now()) diffsecond,b.host,b.user,concat('kill ',b.ID,' ;') killsql,b.db,
IFNULL(b.INFO,a.trx_query) runsql
from information_schema.innodb_trx a left join
information_schema.PROCESSLIST b on a.trx_mysql_thread_id=b.ID
where timestampdiff(SECOND,trx_started,now()) >=1
order by 1 desc limit 20;

show open tables where in_use >=1;

Crontab執行排程和清理10天前的日誌

*/1 * * * *  sh /root/shell/sg_monitor_master.sh > /dev/null 2>&1
1 1 * * *  find /root/monitor/ -name "20*" -type d -mtime +10 -exec rm -rf {}  \; > /dev/null 2>&1

這樣每隔10秒就有下面2個檔案：

可以結合慢SQL和這2個檔案，監控出出問題時當前的資料庫的SQL執行情況，找出問題。

2，從庫突然延遲

因為當時公司是做線上教育的，但從庫延遲幾十秒，對他們影響很大，同時領導就會收到報警簡訊，釘釘群裡叫，就要查是什麼原因導致的從庫延遲，一種方法是檢視上面的監控處理的SQL獲取資訊，另外當時還有解析出binlog資訊，查出具體的SQL，看是什麼SQL導致的，具體做法：

1，從騰訊雲的下載出問題時間的binlog日誌本地的機器

2，根據出問題的時間範圍，解析binlog日誌，如下： 

mysqlbinlog --no-defaults -vv --base64-output=decode-rows --start-datetime='2020-08-18 11:20:00' --stop-datetime='2020-08-18 12:03:00' mysql-bin.000203 >log.sql

3，解析出binlog日誌後，用notepad++開啟檔案，仔細檢視執行的SQL日誌，分析出SQL，這就是細心活。如果查到具體表，可以用上grep過濾，如下： 

1, grep user_0  -A 10 -B 10 >/data/61.txt
2, mysqlbinlog --start-datetime="2019-07-08 9:32:00" --stop-datetime="2019-07-09 11:20:00" -v --base64-output=DECODE-ROWS binlog.000001 | grep -A4 'INSERT' > test.sql




   4，結合上面資訊，發出SQL，讓研發同學去修改業務。


 注意binlog：


    1，主庫開啟gtid後，pos位置點，每個binlog日誌檔案開始的pos都是從1開始計算


    2，binlog的replace，會轉成對應的idelete和insert，或者update等


    3，binlog： 執行的SQL都是帶有庫名

         --base64-output引數用來控制binlog部分是否顯示出來的，指定為decode-rows表示不顯示binglog部分


       加-v與加-vv的區別


         加-vv


         ### UPDATE `online`.`ol_teacher_inversion_rate_list` ### WHERE ### @1=595135615 /* INT meta=0 nullable=0 is_null=0 */


        加-v


          ### UPDATE `online`.`ol_teacher_inversion_rate_list` ### WHERE ### @1=595135615


      少一個v，少後面的欄位型別資訊


     加--base64-output=DECODE-ROWS與不加的區別：


     加：--base64-output=DECODE-ROWS


      不顯示原始binlog的二進位制資訊 ：如 BINLOG ' JV7gWg8QJwAAdwAA.......'




    4，binlog批次刪除

     如：DELETE FROM `online`.`ol_task_agents_fixed` WHERE `record_date` = '2021-04-21'


     在binlog會一條一條記錄，刪除5000條，會有5000條delete語句，而且是同一個事務。


  3，記錄原始SQL


     當時在公司，公司技術VP說要記錄執行的原始SQL，這樣大資料讀取binlog，把這個原始SQL保留起來，日後審計時就可以透過原始SQL發現誰亂改線上業務資料，同時要把研發人員每次業務要改資料的SQL郵件抄送給他。查詢發現mysql還有這樣的引數： binlog_rows_query_log_events引數


      預設配置下，ROW格式二進位制日誌只記錄資料發生的變化，並不會記錄什麼語句導致資料發生變化，而出於審計或者處理bug的需求，需要了解導致資料變化的SQL語句，MYSQL提供了binlog_rows_query_log_events來控制是否在二進位制中存放"原始SQL"。開啟後如下：   




     後來在主庫上開啟該引數，大資料就記錄主庫的SQL執行情況，要監控誰有亂修改更新線上業務資料，但後面一直沒用這個資料去查，反而大資料說記錄的執行SQL資料量太大，不得不縮短資料保留日期。










相關文章