You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@ranger.apache.org by "Xuze Yang (Jira)" <ji...@apache.org> on 2022/03/24 06:58:00 UTC
[jira] [Comment Edited] (RANGER-3681) Ranger Database deadlock when createPolicy is running parallel
[ https://issues.apache.org/jira/browse/RANGER-3681?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17511620#comment-17511620 ]
Xuze Yang edited comment on RANGER-3681 at 3/24/22, 6:57 AM:
-------------------------------------------------------------
add some details：
# I wrote a test demo which calles the createPolicy() method 100 times using two threads. The results showed that only half of the policies were successfully created, and the other half failed to create due to deadlock.
# When I change the isolation level of mysql database session to rc (READ-COMMITTED), there will be no deadlock exception.
# The structure of the x_policy_ref_resource table is:
{noformat}
CREATE TABLE `x_policy_ref_resource` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`guid` varchar(1024) DEFAULT NULL,
`create_time` datetime DEFAULT NULL,
`update_time` datetime DEFAULT NULL,
`added_by_id` bigint(20) DEFAULT NULL,
`upd_by_id` bigint(20) DEFAULT NULL,
`policy_id` bigint(20) NOT NULL,
`resource_def_id` bigint(20) NOT NULL,
`resource_name` varchar(4000) DEFAULT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `x_policy_ref_res_UK_polId_resDefId` (`policy_id`,`resource_def_id`),
KEY `x_policy_ref_res_FK_added_by_id` (`added_by_id`),
KEY `x_policy_ref_res_FK_upd_by_id` (`upd_by_id`),
KEY `x_policy_ref_res_FK_resource_def_id` (`resource_def_id`),
CONSTRAINT `x_policy_ref_res_FK_added_by_id` FOREIGN KEY (`added_by_id`) REFERENCES `x_portal_user` (`id`),
CONSTRAINT `x_policy_ref_res_FK_policy_id` FOREIGN KEY (`policy_id`) REFERENCES `x_policy` (`id`),
CONSTRAINT `x_policy_ref_res_FK_resource_def_id` FOREIGN KEY (`resource_def_id`) REFERENCES `x_resource_def` (`id`),
CONSTRAINT `x_policy_ref_res_FK_upd_by_id` FOREIGN KEY (`upd_by_id`) REFERENCES `x_portal_user` (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=7654 DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC{noformat}
was (Author: xuze yang):
add some details：
# I wrote a test demo which calles the createPolicy() method 100 times using two threads. The results showed that only half of the policies were successfully created, and the other half failed to create due to deadlock.
# When I change the isolation level of mysql database session to rc (READ-COMMITTED), there will be no deadlock exception.
# The structure of the x_policy_ref_resource table is:
{noformat}
CREATE TABLE `x_policy_ref_resource` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`guid` varchar(1024) DEFAULT NULL,
`create_time` datetime DEFAULT NULL,
`update_time` datetime DEFAULT NULL,
`added_by_id` bigint(20) DEFAULT NULL,
`upd_by_id` bigint(20) DEFAULT NULL,
`policy_id` bigint(20) NOT NULL,
`resource_def_id` bigint(20) NOT NULL,
`resource_name` varchar(4000) DEFAULT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `x_policy_ref_res_UK_polId_resDefId` (`policy_id`,`resource_def_id`),
KEY `x_policy_ref_res_FK_added_by_id` (`added_by_id`),
KEY `x_policy_ref_res_FK_upd_by_id` (`upd_by_id`),
KEY `x_policy_ref_res_FK_resource_def_id` (`resource_def_id`),
CONSTRAINT `x_policy_ref_res_FK_added_by_id` FOREIGN KEY (`added_by_id`) REFERENCES `x_portal_user` (`id`),
CONSTRAINT `x_policy_ref_res_FK_policy_id` FOREIGN KEY (`policy_id`) REFERENCES `x_policy` (`id`),
CONSTRAINT `x_policy_ref_res_FK_resource_def_id` FOREIGN KEY (`resource_def_id`) REFERENCES `x_resource_def` (`id`),
CONSTRAINT `x_policy_ref_res_FK_upd_by_id` FOREIGN KEY (`upd_by_id`) REFERENCES `x_portal_user` (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=7654 DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC{noformat}
> Ranger Database deadlock when createPolicy is running parallel
> --------------------------------------------------------------
>
> Key: RANGER-3681
> URL: https://issues.apache.org/jira/browse/RANGER-3681
> Project: Ranger
> Issue Type: Bug
> Components: admin
> Affects Versions: 2.1.0
> Environment: ranger-version: 2.1.0
> mysql-verison: 5.7.34-log
> mysql-engine: InnoDB
> mysql-isolation-level: REPEATABLE-READ
> Reporter: Xuze Yang
> Assignee: Xuze Yang
> Priority: Major
>
> h1. Error
> ranger-log：
> {noformat}
> 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)
> ...{noformat}
> mysql-deadlock：
> {noformat}
> ------------------------
> 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){noformat}
> h1. Description
> In our production environment, we may create ranger hive policy in parallel. In this case it will occasionally report deadlock errors. I turned on the general_log in mysql, and captured the sql when the deadlock exception occurred, as shown below (some sql was simplified, and only the sql that caused the deadlock was kept):
> {noformat}
> 2022-03-21T20:16:26.776033+08:00 239903 Query DELETE FROM x_policy_ref_resource WHERE (policy_id = 16032)
> 2022-03-21T20:16:26.776463+08:00 239902 Query DELETE FROM x_policy_ref_resource WHERE (policy_id = 16033)
> 2022-03-21T20:16:26.784333+08:00 239903 Query 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 23:16:26.766', 16032, 5, 'database', '2022-03-20 23:16:26.783', 1)
> 2022-03-21T20:16:26.785484+08:00 239902 Query 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 23:16:26.767', 16033, 5, 'database', '2022-03-20 23:16:26.784', 1)
> 2022-03-21T20:16:26.787844+08:00 239903 Query 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 23:16:26.766', 16032, 8, 'column', '2022-03-20 23:16:26.786', 1)
> 2022-03-21T20:16:26.788728+08:00 239903 Query 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 23:16:26.766', 16032, 6, 'table', '2022-03-20 23:16:26.787', 1)
> 2022-03-21T20:16:26.810405+08:00 239902 Query rollback
> 2022-03-21T20:16:26.810781+08:00 239902 Query SET autocommit=1
> 2022-03-21T20:16:26.831309+08:00 239903 Query commit{noformat}
> I exported the data in the x_policy_ref_resource table using mysqldump and simulated it in the local environment and found that there is a deadlock when the sql of the two transactions is executed as following order：
> ||transation1||transation2||
> |begin|begin|
> |DELETE FROM x_policy_ref_resource WHERE (policy_id = 16032);| |
> | |DELETE FROM x_policy_ref_resource WHERE (policy_id = 16033);|
> |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 23:16:26.766', 16032, 5, 'database', '2022-03-20 23:16:26.783', 1);| |
> | |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 23:16:26.767', 16033, 5, 'database', '2022-03-20 23:16:26.784', 1);|
> # When transaction1 and transaction2 execute delete sql, they will both obtain gap lock, because gap locks are compatible.
> # Then transaction 1 executes insert sql, it will try to acquire the insert intention lock, which conflicts with the gap lock held by transaction 2, and enters the lock waiting state.
> # Finally, transaction2 executes insert sql, and also tries to acquire the insert intention lock, which conflicts with the gap lock held by transaction1. At this point, it is caught in a cycle where transaction1 waits for transaction 2 to release the gap lock, and transaction2 waits for transaction1 to release the gap lock. Two transactions waiting for each other to release locks eventually lead to a deadlock.
>
--
This message was sent by Atlassian Jira
(v8.20.1#820001)