数据库内核月报 - 2016 / 07

MySQL · 最佳实战 · 审计日志实用案例分析

审计日志是RDS安全策略中非常重要的一环,它采集了数据库中所有的访问请求,包括常见的insert,update,delete,select,alter,drop,create语句,

还有一些比如set,commit,rollback命令语句。有了这些日志后可以帮助我们进行问题回溯,分析问题。下面这则案例讲述如何使用审计日志来分析只读实例延迟问题,如果没有审计日志我们很难想象该问题该如何解决。

问题描述:

一客户使用了2个RDS只读节点来承担业务的读流量,两个RDS的资源规格和业务流量完全一样,但是离奇的发现两个只读中有一个实例出现了延迟,让用户百思不得其解:

screenshot

只读Slave1出现延迟(图一):

screenshot

只读Slave2正常同步(图二):

screenshot

分析:

  1. 从上图监控可以看出延迟的曲线是一条直线,出现这样的直线通常是数据库的复制线程被block,导致slave一直无法完成与主库的数据同步,
    比如:主库的一个超大事务或DDL传到备库。

  2. 但是两个只读实例中只有一个只读实例出现延迟(图二),那么需要看一下出现延迟的时候只读实例当时的线程状态,以此来判断出问题所在。

问题排查:

  • 检查延迟只读实例slave2在延迟期间的数据库快照,发现数据库中有大量的Waiting for table metadata lock 等待
    (出现延迟时候可以使用show processlist将数据库的线程状态保存下来):
    表:xxx_user
    SQL:
SELECT user_id ...... FROM xxx_user where latest_time >= DATE_FORMAT('2016/06/15 23:40:09.000000000','%Y-%m-%d %k:%i:%s')  

screenshot

分析:

  1. 出现select等待MDL锁的原因通常是该表上有DDL操作,在DDL操作的过程中会加上一个MDL锁,但是如果该表上有大查询,大事务或者未提交的事务,则会导致DDL操作无法获得MDL锁,进而阻塞住该表上的所有查询。

  2. 由于当前实例是只读实例,所以DDL操作来源于主库,所以我们看一下主库是否真正在该表上有DDL操作。

  • 从后端审计日志中果然发现在2016-06-17 00:41:17 时主库做了一次DDL操作,但是该DDL操作执行非常快,那么很有可能DDL传递到只读节点的时候,由于只读节点上该表有一个未提交的事务或者查询,导致DDL操作被blcok。

screenshot

  • 在诊断快照中发现了一个事务在2016-06-16 19:17:09 就已经开始了,所以该事务很有可能就是导致DDL无法获取MDL锁的根源,那我们看一下这个事务做了哪些事情,线程id:1435503。

screenshot

  • 查看审计日志:

通过查看审计日志发现,线程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掉之后只读节点的延迟迅速下降。

screenshot

screenshot

screenshot

总结:

  1. 此次slave延迟的原因为只读节点有未提交的事务导致主库的DDL被阻塞,所以在日常做DDL的过程中一定要观察数据库中是否存在大查询,大事务或者未提交的事务。

  2. 善于使用show processlist来保存数据库的快照,如果该问题出现在自建数据库中,也是需要按照上述的方法进行排查,但是如果没有RDS的审计日志,排查问题起来会非常麻烦,可以通过审计日志去发现RDS中执行过的是有SQL,RDS不是黑盒子。

  3. 只读实例延迟排查常见思路:一看资源是否达到瓶颈;二看线程状态是否有锁;三判断是否存在大事务或未提交的事务。

  4. 要注意set autocommit=0的使用,一定要在语句结束后显式commit掉,不然会导致数据库中存在长时间未提交的事务,进而引发很多潜在的问题。

  5. 为了审计以及排查问题方便,建议打开审计日志。