今天分析了另外一個(gè)關(guān)于數(shù)據(jù)庫(kù)延遲跳動(dòng)的問(wèn)題，也算是比較典型，這個(gè)過(guò)程中也有一些分析問(wèn)題的方法和技巧工參考。

首先在高可用檢測(cè)中，有一套環(huán)境的檢測(cè)時(shí)斷時(shí)續(xù)，經(jīng)過(guò)排查發(fā)現(xiàn)是數(shù)據(jù)庫(kù)產(chǎn)生了延遲，在登錄到從庫(kù)show slave status查看，會(huì)發(fā)現(xiàn)Seconds_behind_master的值是不斷跳動(dòng)的，即從0~39~0~39這樣的頻率不斷跳動(dòng)，讓人很搓火。

查看數(shù)據(jù)庫(kù)的相關(guān)日志發(fā)現(xiàn)竟然沒(méi)有任何可以參考的日志記錄，怎么分析這個(gè)問(wèn)題呢，我們先來(lái)復(fù)現(xiàn)，于是我按照節(jié)奏抓取了3次問(wèn)題出現(xiàn)的日志，即通過(guò)show slave status連續(xù)監(jiān)測(cè)，抓取show slave status輸出的結(jié)果保存下來(lái)，這樣我們就得到了一個(gè)問(wèn)題發(fā)生過(guò)程中的偏移量變化，而這個(gè)變化則是在SQLThread在回放過(guò)程中產(chǎn)生的問(wèn)題。

比如下面的一段輸出，我截取的是Slave端的relay log進(jìn)行分析，相應(yīng)的字段為Relay_Log_Pos

所以很快得到了偏移量的變化情況：385983806 ，386062813 ，386125580

接著我使用mysqlbinlog開(kāi)始分析這些日志過(guò)程中的明細(xì)，根據(jù)如下的命令可以很快得到轉(zhuǎn)儲(chǔ)的日志中相關(guān)的表有3張。

我逐步分析了每張表的數(shù)據(jù)操作情況，得到的信息還是比較有限，繼續(xù)做更進(jìn)一步的分析，比如我們分析一下整個(gè)日志中的事務(wù)量大?。?/p>

可以看到是5K左右，算是比較大了，而這些額外的信息從哪里獲得呢，我在主庫(kù)開(kāi)啟了general_log，這樣就能夠得到更細(xì)粒度的操作日志了。

進(jìn)一步分析發(fā)現(xiàn)，整個(gè)業(yè)務(wù)使用了顯示事務(wù)的方式：SET autocommit=0，整個(gè)事務(wù)中包含了幾個(gè)大SQL，里面存儲(chǔ)了很多操作日志明細(xì)，而且在事務(wù)操作過(guò)程中還基于Mybatis框架調(diào)用了多次select count（1） from xxx的操作。

經(jīng)過(guò)和業(yè)務(wù)溝通也基本明確了以上問(wèn)題。