问题不难,但藏得有点深

原创
2022/04/03 23:03
阅读数 141


【问题现象】


上周,测试环境偶现创建策略失败,查看ranger的日志发现有如下的错误信息:


2022-03-21 20:14:29,685 [http-bio-6080-exec-13] ERROR org.apache.ranger.rest.ServiceREST (ServiceREST.java:1709) - createPolicy(RangerPolicy={id={null} guid={null} isEnabled={true} createdBy={null} updatedBy={null} createTime={null} updateTime={null} version={1} service={default-Hive} name={dcp-desensitize_a162c40cdc0140b1848b98415575be6c-1647864869626} policyType={0} policyPriority={0} description={} resourceSignature={4f15e3de95c81650ad869cb93a8c47a132bbec54bdf5de8c01f5075c19754cd7} isAuditEnabled={true} serviceType={null} resources={database={RangerPolicyResource={values={dcp } isExcludes={false} isRecursive={false} }} column={RangerPolicyResource={values={* } isExcludes={false} isRecursive={false} }} table={RangerPolicyResource={values={desensitize_a162c40cdc0140b1848b98415575be6c } isExcludes={false} isRecursive={false} }} } policyLabels={Consoler } policyConditions={} policyItems={RangerPolicyItem={accessTypes={RangerPolicyItemAccess={type={all} isAllowed={true} }} users={tangbiao2 } groups={} roles={} conditions={} delegateAdmin={false} }} denyPolicyItems={} allowExceptions={} denyExceptions={} dataMaskPolicyItems={} rowFilterPolicyItems={} options={} validitySchedules={, zoneName=null, isDenyAllElse={false} }}) failed
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
Error Code: 1213
Call: INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (?, ?, ?, ?, ?, ?, ?)
        bind => [7 parameters bound]
Query: ValueReadQuery(name="x_policy_ref_resource_SEQ" sql="SELECT LAST_INSERT_ID()")
        at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:868)
        at sun.reflect.GeneratedMethodAccessor98.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:301)
        at com.sun.proxy.$Proxy30.flush(Unknown Source)
        at org.apache.ranger.common.db.BaseDao.batchCreate(BaseDao.java:102)
        ...


与测试人员一番沟通,找到了一个有用信息:有并发调用创建策略的接口。


然而光看ranger的日志,即便结合源码也没有什么特别的发现,所以打算从mysql的日志看看有什么发现,果不其然,在mysql的日志中,发现出现了"死锁"的日志,具体如下所示:


------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-03-21 09:47:22 0x7ff3a4859700
*** (1) TRANSACTION:
TRANSACTION 7036760, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 23 lock struct(s), heap size 1136, 12 row lock(s), undo log entries 2
MySQL thread id 27293, OS thread handle 140684415063808, query id 383930 192.168.0.76 DHCloudBG update
INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 12:47:22.666', 13921, 5, 'database', '2022-03-20 12:47:22.681', 1)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 531 page no 4 n bits 376 index x_policy_ref_res_UK_polId_resDefId of table `ranger`.`x_policy_ref_resource` trx id 7036760 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;
*** (2) TRANSACTION:
TRANSACTION 7036759, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
23 lock struct(s), heap size 1136, 12 row lock(s), undo log entries 2
MySQL thread id 27295, OS thread handle 140684413998848, query id 383932 192.168.0.76 DHCloudBG update
INSERT INTO x_policy_ref_resource (ADDED_BY_ID, CREATE_TIME, policy_id, resource_def_id, resource_name, UPDATE_TIME, UPD_BY_ID) VALUES (1, '2022-03-20 12:47:22.666', 13920, 5, 'database', '2022-03-20 12:47:22.682', 1)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 531 page no 4 n bits 376 index x_policy_ref_res_UK_polId_resDefId of table `ranger`.`x_policy_ref_resource` trx id 7036759 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 531 page no 4 n bits 376 index x_policy_ref_res_UK_polId_resDefId of table `ranger`.`x_policy_ref_resource` trx id 7036759 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;*** WE ROLL BACK TRANSACTION (2)


问题分析


为什么会产生死锁,怎样才会出现死锁,结果会怎样?要回答这些问题,还得先来了解下mysql的锁机制。


mysql的innodb有4个隔离级别:

隔离级别
脏读
不可重复读
幻读
未提交读(read-uncommitted)



已提交读(read-committed)



可重复读(repeatable-read)



可串行化(serializable)




实际使用中,一般很少使用未提交读和可串行读,采用最多的则是read-committed(通常也是其他数据库的默认选择)。


然而因为一些历史遗留问题,mysql在5.1.5版本前,binlog的格式只能为statement,在这种格式下若不选择可重复读隔离级别,则主从数据可能会出现不一致的问题。而在5.1.5版本之后,binlog有3种格式可选:statement,row和mixed。


在我们的实际环境中,binlog的格式为mixed,即statement和row格式的混合,目的是为了在保证主从数据一致的前提下精简binlog。隔离级别则是可重复读


在可重复读隔离级别中存在一个间隙锁,这个正是问题存在的根本原因。


先举例说明下什么是间隙锁,以及间隙锁的效果是怎样的。

仿照ranger的数据库表设计,建立如下表


CREATE TABLE `hncscwc` (
`id` int AUTO_INCREMENT,
`a` int,
`b` int,
`c` int,
PRIMARY KEY (`id`),
UNIQUE KEY `ux_a_b` (`a`, `b`)
) ENGINE=InnoDB;


然后插入如下数据:


mysql> select * from hncscwc;
+----+----+-----+-----+
| id | a  | b   | c   |
+----+----+-----+-----+
|
  1 |  1 |  10 | 100 |
|  2 |  3 |  20 |  99 |
|
  3 |  5 |  50 |  80 |
+----+----+-----+-----+


然后依次执行如下两个事务(注意执行时序)

其中事务1和事务2的delete语句均会成功;事务1在执行insert语句时会被阻塞,而事务2再次执行insert语句时,会出现报错(ERROR 1213: Deadlock found when trying to get lock;),此后事务2出现回滚,再然后原本事务1中阻塞的insert语句则可以往下成功执行。


如果数据库的隔离级别为可重复读级别, 并且delete的where子句的字段不是主键或唯一索引,则delete加锁的类型为间隙锁数据库会向左扫描扫到第一个比给定参数小的值,向右扫描到第一个比给定参数大的值,然后以此为界(包含这两个值)构成一个区间,并对该区间加锁,这个就是间隙锁。


间隙锁之间是兼容的,所以上面的两个事务执行delete时都能持有间隙锁。


此后,事务1进行insert时,其加锁过程是先在插入的间隙上获取插入意向锁,插入数据后再获取插入行上的排他锁。但是在获取意向锁时与事务2持有的间隙锁冲突,导致阻塞进入等待状态。


同样,事务2在进行insert时也因为获取意向锁与事务1持有的间隙锁冲突,进而陷入循环等待的死锁状态。


【问题解决】


了解了间隙锁后,再来看ranger中的这个问题,两次并发的创建策略的事务过程中,会先对其中一个表的数据进行删除,然后再真正插入数据,两个事务在执行时序上穿插进行导致出现了死锁问题


原因彻底了解后,剩下的自然就是怎样在改动最小的情况下修复问题了。

这里可行的方案包括:


  • 修改调整数据库的隔离级别

  • 对创建策略过程中的删除与插入不放在一个事务中执行

  • 创建策略不进行删除动作

  • 创建策略的删除动作时,先根据记录查主键,如果存在则按主键进行删除,规避间隙锁的问题。


经过各方面的权衡,最终选择了最后一个方案,因为其他方案要么不能彻底解决问题,要么会引发其他问题。此外还对对相关类似的地方一并进行了修改,详见


https://issues.apache.org/jira/browse/RANGER-3681?jql=project%20%3D%20RANGER



【总结】


通过ranger创建策略失败的偶现问题,了解了msyql中间隙锁的机制,最后并合理运用对其进行了规避处理。


好了,这就是本文的全部内容,如果觉得本文对你有帮助,三(拒)连(绝)走(白)起(嫖),也欢迎加我微信交流~





本文分享自微信公众号 - hncscwc(gh_383bc7486c1a)。
如有侵权,请联系 support@oschina.cn 删除。
本文参与“OSC源创计划”,欢迎正在阅读的你也加入,一起分享。

展开阅读全文
加载中

作者的其它热门文章

打赏
0
0 收藏
分享
打赏
0 评论
0 收藏
0
分享
返回顶部
顶部