審計日志是rds安全政策中非常重要的一環,它采集了資料庫中所有的通路請求,包括常見的insert,update,delete,select,alter,drop,create語句,
還有一些比如set,commit,rollback指令語句。有了這些日志後可以幫助我們進行問題回溯,分析問題。下面這則案例講述如何使用審計日志來分析隻讀執行個體延遲問題,如果沒有審計日志我們很難想象該問題該如何解決。
一客戶使用了2個rds隻讀節點來承擔業務的讀流量,兩個rds的資源規格和業務流量完全一樣,但是離奇的發現兩個隻讀中有一個執行個體出現了延遲,讓使用者百思不得其解:
隻讀slave1出現延遲(圖一):
隻讀slave2正常同步(圖二):
從上圖監控可以看出延遲的曲線是一條直線,出現這樣的直線通常是資料庫的複制線程被block,導緻slave一直無法完成與主庫的資料同步,
比如:主庫的一個超大事務或ddl傳到備庫。
但是兩個隻讀執行個體中隻有一個隻讀執行個體出現延遲(圖二),那麼需要看一下出現延遲的時候隻讀執行個體當時的線程狀态,以此來判斷出問題所在。
檢查延遲隻讀執行個體slave2在延遲期間的資料庫快照,發現資料庫中有大量的waiting for table metadata lock 等待
(出現延遲時候可以使用show processlist将資料庫的線程狀态儲存下來):
表:xxx_user
sql:
出現select等待mdl鎖的原因通常是該表上有ddl操作,在ddl操作的過程中會加上一個mdl鎖,但是如果該表上有大查詢,大事務或者未送出的事務,則會導緻ddl操作無法獲得mdl鎖,進而阻塞住該表上的所有查詢。
由于目前執行個體是隻讀執行個體,是以ddl操作來源于主庫,是以我們看一下主庫是否真正在該表上有ddl操作。
從後端審計日志中果然發現在2016-06-17 00:41:17 時主庫做了一次ddl操作,但是該ddl操作執行非常快,那麼很有可能ddl傳遞到隻讀節點的時候,由于隻讀節點上該表有一個未送出的事務或者查詢,導緻ddl操作被blcok。
在診斷快照中發現了一個事務在2016-06-16 19:17:09 就已經開始了,是以該事務很有可能就是導緻ddl無法擷取mdl鎖的根源,那我們看一下這個事務做了哪些事情,線程id:1435503。
檢視審計日志:
通過檢視審計日志發現,線程id:1435503最後一次設定autocommit=0,時間是在16-06-16 14:10:03,之後對xx_user這個表執行了一個select,時間是在2016-06-16 19:17:09,但是一直沒有送出,是以就是這個語句拿着mdl鎖,直到2016-06-16 05:08:42 被kill後才被釋放。該線程kill掉之後隻讀節點的延遲迅速下降。
此次slave延遲的原因為隻讀節點有未送出的事務導緻主庫的ddl被阻塞,是以在日常做ddl的過程中一定要觀察資料庫中是否存在大查詢,大事務或者未送出的事務。
善于使用show processlist來儲存資料庫的快照,如果該問題出現在自建資料庫中,也是需要按照上述的方法進行排查,但是如果沒有rds的審計日志,排查問題起來會非常麻煩,可以通過審計日志去發現rds中執行過的是有sql,rds不是黑盒子。
隻讀執行個體延遲排查常見思路:一看資源是否達到瓶頸;二看線程狀态是否有鎖;三判斷是否存在大事務或未送出的事務。
要注意set autocommit=0的使用,一定要在語句結束後顯式commit掉,不然會導緻資料庫中存在長時間未送出的事務,進而引發很多潛在的問題。
為了審計以及排查問題友善,建議打開審計日志。