You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@sentry.apache.org by "Na Li (JIRA)" <ji...@apache.org> on 2018/09/12 04:18:00 UTC
[jira] [Commented] (SENTRY-2185) Performance Issue: Saving
MAuthzPathsMapping should be done in batch for path full snapshot
[ https://issues.apache.org/jira/browse/SENTRY-2185?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16611570#comment-16611570 ]
Na Li commented on SENTRY-2185:
-------------------------------
1) DataNucleus does not batch certain inserts
1.1) batch inserting is disabled in DataNucleus when objects being inserted are using identity value generation strategy.
{code}
The statements that DataNucleus currently allows for batching are
Insert of objects (from version 2.1.1). This is not enabled when objects being inserted are using identity value generation strategy
Delete of objects
Insert of container elements/keys/values
Delete of container elements/keys/values
http://www.datanucleus.org/products/accessplatform_3_0/rdbms/statement_batching.html
{code}
1.2) In package.jdo, AUTHZ_PATHS_MAPPING and AUTHZ_PATH use identity value generation strategy
{code}
<class name="MAuthzPathsMapping" identity-type="datastore" table="AUTHZ_PATHS_MAPPING" detachable="true">
<datastore-identity>
<column name="AUTHZ_OBJ_ID"/>
</datastore-identity>
<index name="AUTHZ_SNAPSHOT_ID_INDEX" unique="false">
<field name="authzSnapshotID"/>
</index>
<class name="MPath" identity-type="datastore" table="AUTHZ_PATH" detachable="true">
<datastore-identity>
<column name="PATH_ID"/>
</datastore-identity>
<field name="path">
<column name="PATH_NAME" length="4000" jdbc-type="VARCHAR"/>
</field>
</class>
{code}
1.3) This means the following inserts are not batched.
{code}
INSERT INTO AUTHZ_PATHS_MAPPING (AUTHZ_OBJ_ID,AUTHZ_OBJ_NAME,AUTHZ_SNAPSHOT_ID,CREATE_TIME_MS)
INSERT INTO AUTHZ_PATH (PATH_ID,PATH_NAME,AUTHZ_OBJ_ID)
{code}
2. Run unit test TestSentryStore.testPersistAndReplaceANewPathsImage(), the statement "sentryStore.persistFullPathsImage(authzPaths, notificationID);" results in the following output. It confirms that those inserts are not batched.
{code}
2018-09-11 22:34:12,699 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext "org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@52d6cd34" with txn="org.datanucleus.TransactionImpl@44be69aa"
2018-09-11 22:34:12,700 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Transaction created [DataNucleus Transaction, ID=Xid= , enlisted resources=[]]
2018-09-11 22:34:12,700 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Transaction begun for ExecutionContext org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4 (optimistic=false)
2018-09-11 22:34:12,702 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compiling "SELECT FROM org.apache.sentry.provider.db.service.model.MSentryHmsNotification WHERE notificationId >= currentNotificationId PARAMETERS long currentNotificationId"
2018-09-11 22:34:12,715 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compile Time = 13 ms
2018-09-11 22:34:12,715 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] QueryCompilation:
[filter:DyadicExpression{PrimaryExpression{notificationId} >= ParameterExpression{currentNotificationId}}]
[symbols: this type=org.apache.sentry.provider.db.service.model.MSentryHmsNotification, currentNotificationId type=long]
2018-09-11 22:34:12,715 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compiling "SELECT FROM org.apache.sentry.provider.db.service.model.MSentryHmsNotification WHERE notificationId >= currentNotificationId PARAMETERS long currentNotificationId" for datastore
2018-09-11 22:34:12,716 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Managing Persistence of Class : org.apache.sentry.provider.db.service.model.MSentryHmsNotification [Table : SENTRY_HMS_NOTIFICATION_ID, InheritanceStrategy : new-table]
2018-09-11 22:34:12,716 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table SENTRY_HMS_NOTIFICATION_ID will manage the persistence of the fields for class org.apache.sentry.provider.db.service.model.MSentryHmsNotification (inheritance strategy="new-table")
2018-09-11 22:34:12,716 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "SENTRY_HMS_NOTIFICATION_ID.NOTIFICATION_ID" added to internal representation of table.
2018-09-11 22:34:12,716 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MSentryHmsNotification.notificationId] -> Column(s) [SENTRY_HMS_NOTIFICATION_ID.NOTIFICATION_ID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
2018-09-11 22:34:12,716 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table/View SENTRY_HMS_NOTIFICATION_ID has been initialised
2018-09-11 22:34:12,717 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1d6d1d42 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" opened with isolation level "serializable" and auto-commit=false
2018-09-11 22:34:12,717 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction started with connection "com.jolbox.bonecp.ConnectionHandle@27329d2a" with isolation "serializable"
2018-09-11 22:34:12,724 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Check of existence of SENTRY_HMS_NOTIFICATION_ID returned no table
2018-09-11 22:34:12,725 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating table SENTRY_HMS_NOTIFICATION_ID
2018-09-11 22:34:12,725 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] CREATE TABLE SENTRY_HMS_NOTIFICATION_ID
(
NOTIFICATION_ID BIGINT NOT NULL
)
2018-09-11 22:34:12,737 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 12 ms
2018-09-11 22:34:12,771 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Loading column info for table(s) "SENTRY_HMS_NOTIFICATION_ID, SENTRY_VERSION" in Catalog "", Schema ""
2018-09-11 22:34:12,889 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info loaded for Catalog "", Schema "", 2 tables, time = 118 ms
2018-09-11 22:34:12,889 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info retrieved for table "SENTRY_HMS_NOTIFICATION_ID" : 1 columns found
2018-09-11 22:34:12,908 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating index "SENTRY_HMS_NOTIF_ID_INDEX" in catalog "" schema ""
2018-09-11 22:34:12,908 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] CREATE INDEX SENTRY_HMS_NOTIF_ID_INDEX ON SENTRY_HMS_NOTIFICATION_ID (NOTIFICATION_ID)
2018-09-11 22:34:12,983 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 75 ms
2018-09-11 22:34:12,983 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction committing with connection "com.jolbox.bonecp.ConnectionHandle@27329d2a"
2018-09-11 22:34:12,985 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction closing with connection "com.jolbox.bonecp.ConnectionHandle@27329d2a"
2018-09-11 22:34:12,985 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1d6d1d42 [conn=com.jolbox.bonecp.ConnectionHandle@27329d2a, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" is being committed.
2018-09-11 22:34:12,985 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1d6d1d42 [conn=com.jolbox.bonecp.ConnectionHandle@27329d2a, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" closed
2018-09-11 22:34:12,993 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Query generation selecting all fields of "org.apache.sentry.provider.db.service.model.MSentryHmsNotification" since nondurable identity
2018-09-11 22:34:12,994 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compile Time for datastore = 279 ms
2018-09-11 22:34:12,994 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT FROM org.apache.sentry.provider.db.service.model.MSentryHmsNotification WHERE notificationId >= currentNotificationId PARAMETERS long currentNotificationId Query compiled to datastore query "SELECT 'org.apache.sentry.provider.db.service.model.MSentryHmsNotification' AS NUCLEUS_TYPE,A0.NOTIFICATION_ID FROM SENTRY_HMS_NOTIFICATION_ID A0 WHERE A0.NOTIFICATION_ID >= ?"
2018-09-11 22:34:12,994 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Not caching the datastore compilation since some parameters are evaluated during the compilation and arent present in the final datastore-specific query
2018-09-11 22:34:12,994 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=null, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" opened with isolation level "repeatable-read" and auto-commit=false
2018-09-11 22:34:12,995 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Running enlist operation on resource: org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@dd2856e, error code TMNOFLAGS and transaction: [DataNucleus Transaction, ID=Xid= , enlisted resources=[]]
2018-09-11 22:34:12,995 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" starting for transaction "Xid= " with flags "0"
2018-09-11 22:34:12,995 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection added to the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:12,999 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Executing "SELECT FROM org.apache.sentry.provider.db.service.model.MSentryHmsNotification WHERE notificationId >= currentNotificationId PARAMETERS long currentNotificationId" ...
2018-09-11 22:34:13,021 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@31142d58"
2018-09-11 22:34:13,022 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT 'org.apache.sentry.provider.db.service.model.MSentryHmsNotification' AS NUCLEUS_TYPE,A0.NOTIFICATION_ID FROM SENTRY_HMS_NOTIFICATION_ID A0 WHERE A0.NOTIFICATION_ID >= <2>
2018-09-11 22:34:13,023 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1 ms
2018-09-11 22:34:13,023 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Execution Time = 24 ms
2018-09-11 22:34:13,024 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Listener found initialisation for persistable class org.apache.sentry.provider.db.service.model.MSentryHmsNotification
2018-09-11 22:34:13,025 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d"
2018-09-11 22:34:13,026 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" (id="org.datanucleus.identity.IdentityReference@345cbf40") enlisted in transactional cache
2018-09-11 22:34:13,026 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" being inserted into table "SENTRY_HMS_NOTIFICATION_ID"
2018-09-11 22:34:13,026 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:13,031 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2f4b98f6" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:13,031 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] The requested statement "INSERT INTO SENTRY_HMS_NOTIFICATION_ID (NOTIFICATION_ID) VALUES (?)" has been made batchable
2018-09-11 22:34:13,031 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Batch has been added to statement "INSERT INTO SENTRY_HMS_NOTIFICATION_ID (NOTIFICATION_ID) VALUES (?)" for processing (batch size = 1)
2018-09-11 22:34:13,032 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" (id="org.datanucleus.identity.IdentityReference@345cbf40") added to Level 1 cache (loadedFlags="[Y]")
2018-09-11 22:34:13,032 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compiling "SELECT max(authzSnapshotID) FROM org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId"
2018-09-11 22:34:13,033 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compile Time = 1 ms
2018-09-11 22:34:13,034 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] QueryCompilation:
[result:InvokeExpression{STATIC.max(PrimaryExpression{authzSnapshotID})}]
[symbols: this type=org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId]
2018-09-11 22:34:13,034 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compiling "SELECT max(authzSnapshotID) FROM org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId" for datastore
2018-09-11 22:34:13,035 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Managing Persistence of Class : org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId [Table : AUTHZ_PATHS_SNAPSHOT_ID, InheritanceStrategy : new-table]
2018-09-11 22:34:13,036 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATHS_SNAPSHOT_ID.AUTHZ_SNAPSHOT_ID" added to internal representation of table.
2018-09-11 22:34:13,036 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId.authzSnapshotID] -> Column(s) [AUTHZ_PATHS_SNAPSHOT_ID.AUTHZ_SNAPSHOT_ID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
2018-09-11 22:34:13,036 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table AUTHZ_PATHS_SNAPSHOT_ID will manage the persistence of the fields for class org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId (inheritance strategy="new-table")
2018-09-11 22:34:13,037 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table/View AUTHZ_PATHS_SNAPSHOT_ID has been initialised
2018-09-11 22:34:13,037 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4232b34a [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" opened with isolation level "serializable" and auto-commit=false
2018-09-11 22:34:13,037 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction started with connection "com.jolbox.bonecp.ConnectionHandle@2da16263" with isolation "serializable"
2018-09-11 22:34:13,065 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Check of existence of AUTHZ_PATHS_SNAPSHOT_ID returned no table
2018-09-11 22:34:13,066 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating table AUTHZ_PATHS_SNAPSHOT_ID
2018-09-11 22:34:13,067 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] CREATE TABLE AUTHZ_PATHS_SNAPSHOT_ID
(
AUTHZ_SNAPSHOT_ID BIGINT NOT NULL
)
2018-09-11 22:34:13,113 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 45 ms
2018-09-11 22:34:13,113 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ALTER TABLE AUTHZ_PATHS_SNAPSHOT_ID ADD CONSTRAINT AUTHZ_PATHS_SNAPSHOT_ID_PK PRIMARY KEY (AUTHZ_SNAPSHOT_ID)
2018-09-11 22:34:13,163 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 50 ms
2018-09-11 22:34:13,178 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Loading column info for table(s) "AUTHZ_PATHS_SNAPSHOT_ID, SENTRY_HMS_NOTIFICATION_ID, SENTRY_VERSION" in Catalog "", Schema ""
2018-09-11 22:34:13,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info loaded for Catalog "", Schema "", 3 tables, time = 87 ms
2018-09-11 22:34:13,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info retrieved for table "AUTHZ_PATHS_SNAPSHOT_ID" : 1 columns found
2018-09-11 22:34:13,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction committing with connection "com.jolbox.bonecp.ConnectionHandle@2da16263"
2018-09-11 22:34:13,296 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction closing with connection "com.jolbox.bonecp.ConnectionHandle@2da16263"
2018-09-11 22:34:13,296 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4232b34a [conn=com.jolbox.bonecp.ConnectionHandle@2da16263, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" is being committed.
2018-09-11 22:34:13,297 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4232b34a [conn=com.jolbox.bonecp.ConnectionHandle@2da16263, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" closed
2018-09-11 22:34:13,304 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Compile Time for datastore = 270 ms
2018-09-11 22:34:13,304 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT max(authzSnapshotID) FROM org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId Query compiled to datastore query "SELECT MAX(A0.AUTHZ_SNAPSHOT_ID) FROM AUTHZ_PATHS_SNAPSHOT_ID A0"
2018-09-11 22:34:13,304 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
2018-09-11 22:34:13,304 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext.internalFlush() process finished
2018-09-11 22:34:13,305 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:13,305 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Executing "SELECT max(authzSnapshotID) FROM org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId" ...
2018-09-11 22:34:13,305 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] BATCH [INSERT INTO SENTRY_HMS_NOTIFICATION_ID (NOTIFICATION_ID) VALUES (<1>)]
2018-09-11 22:34:13,306 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1 ms (number of rows = [1]) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2f4b98f6"
2018-09-11 22:34:13,333 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@118dcbbd"
2018-09-11 22:34:13,334 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT MAX(A0.AUTHZ_SNAPSHOT_ID) FROM AUTHZ_PATHS_SNAPSHOT_ID A0
2018-09-11 22:34:13,334 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0 ms
2018-09-11 22:34:13,368 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query : Execution Time = 63 ms
2018-09-11 22:34:13,369 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Listener found initialisation for persistable class org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId
2018-09-11 22:34:13,369 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82"
2018-09-11 22:34:13,370 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" (id="org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId:1") added to Level 1 cache (loadedFlags="[Y]")
2018-09-11 22:34:13,370 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" (id="1") enlisted in transactional cache
2018-09-11 22:34:13,370 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" being inserted into table "AUTHZ_PATHS_SNAPSHOT_ID"
2018-09-11 22:34:13,371 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:13,397 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2b7e8044" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:13,397 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] The requested statement "INSERT INTO AUTHZ_PATHS_SNAPSHOT_ID (AUTHZ_SNAPSHOT_ID) VALUES (?)" has been made batchable
2018-09-11 22:34:13,397 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Batch has been added to statement "INSERT INTO AUTHZ_PATHS_SNAPSHOT_ID (AUTHZ_SNAPSHOT_ID) VALUES (?)" for processing (batch size = 1)
2018-09-11 22:34:13,399 (main) [INFO - org.apache.sentry.provider.db.service.persistent.SentryStore.lambda$persistFullPathsImage$49(SentryStore.java:3450)] Attempting to commit new HMS snapshot with ID = 1
2018-09-11 22:34:13,399 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Listener found initialisation for persistable class org.apache.sentry.provider.db.service.model.MAuthzPathsMapping
2018-09-11 22:34:13,400 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Listener found initialisation for persistable class org.apache.sentry.provider.db.service.model.MPath
2018-09-11 22:34:13,400 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11"
2018-09-11 22:34:13,401 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Managing Persistence of Class : org.apache.sentry.provider.db.service.model.MPath [Table : AUTHZ_PATH, InheritanceStrategy : new-table]
2018-09-11 22:34:13,401 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATH.PATH_ID" added to internal representation of table.
2018-09-11 22:34:13,402 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [DATASTORE_ID] -> Column(s) [AUTHZ_PATH.PATH_ID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.DatastoreIdMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
2018-09-11 22:34:13,402 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Managing Persistence of Class : org.apache.sentry.provider.db.service.model.MAuthzPathsMapping [Table : AUTHZ_PATHS_MAPPING, InheritanceStrategy : new-table]
2018-09-11 22:34:13,402 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATHS_MAPPING.AUTHZ_OBJ_ID" added to internal representation of table.
2018-09-11 22:34:13,403 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [DATASTORE_ID] -> Column(s) [AUTHZ_PATHS_MAPPING.AUTHZ_OBJ_ID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.DatastoreIdMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
2018-09-11 22:34:13,403 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table AUTHZ_PATH will manage the persistence of the fields for class org.apache.sentry.provider.db.service.model.MPath (inheritance strategy="new-table")
2018-09-11 22:34:13,403 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATH.PATH_NAME" added to internal representation of table.
2018-09-11 22:34:13,403 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MPath.path] -> Column(s) [AUTHZ_PATH.PATH_NAME] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
2018-09-11 22:34:13,404 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table/View AUTHZ_PATH has been initialised
2018-09-11 22:34:13,404 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table AUTHZ_PATHS_MAPPING will manage the persistence of the fields for class org.apache.sentry.provider.db.service.model.MAuthzPathsMapping (inheritance strategy="new-table")
2018-09-11 22:34:13,404 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATHS_MAPPING.AUTHZ_OBJ_NAME" added to internal representation of table.
2018-09-11 22:34:13,404 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.authzObjName] -> Column(s) [AUTHZ_PATHS_MAPPING.AUTHZ_OBJ_NAME] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
2018-09-11 22:34:13,424 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATHS_MAPPING.AUTHZ_SNAPSHOT_ID" added to internal representation of table.
2018-09-11 22:34:13,424 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.authzSnapshotID] -> Column(s) [AUTHZ_PATHS_MAPPING.AUTHZ_SNAPSHOT_ID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
2018-09-11 22:34:13,424 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATHS_MAPPING.CREATE_TIME_MS" added to internal representation of table.
2018-09-11 22:34:13,425 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.createTimeMs] -> Column(s) [AUTHZ_PATHS_MAPPING.CREATE_TIME_MS] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
2018-09-11 22:34:13,429 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field [org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths] -> Column(s) [[none]] using mapping of type "org.datanucleus.store.rdbms.mapping.java.CollectionMapping" ()
2018-09-11 22:34:13,431 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "AUTHZ_PATH.AUTHZ_OBJ_ID" added to internal representation of table.
2018-09-11 22:34:13,431 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Table/View AUTHZ_PATHS_MAPPING has been initialised
2018-09-11 22:34:13,432 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@abbe000 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" opened with isolation level "serializable" and auto-commit=false
2018-09-11 22:34:13,432 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction started with connection "com.jolbox.bonecp.ConnectionHandle@3f81621c" with isolation "serializable"
2018-09-11 22:34:13,462 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Check of existence of AUTHZ_PATH returned no table
2018-09-11 22:34:13,463 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating table AUTHZ_PATH
2018-09-11 22:34:13,463 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] CREATE TABLE AUTHZ_PATH
(
PATH_ID BIGINT NOT NULL,
PATH_NAME VARCHAR(4000),
AUTHZ_OBJ_ID BIGINT
)
2018-09-11 22:34:13,482 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 19 ms
2018-09-11 22:34:13,483 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ALTER TABLE AUTHZ_PATH ADD CONSTRAINT AUTHZ_PATH_PK PRIMARY KEY (PATH_ID)
2018-09-11 22:34:13,494 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 11 ms
2018-09-11 22:34:13,545 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Loading column info for table(s) "AUTHZ_PATHS_SNAPSHOT_ID, AUTHZ_PATH, SENTRY_HMS_NOTIFICATION_ID, SENTRY_VERSION, AUTHZ_PATHS_MAPPING" in Catalog "", Schema ""
2018-09-11 22:34:13,641 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info loaded for Catalog "", Schema "", 4 tables, time = 96 ms
2018-09-11 22:34:13,641 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info retrieved for table "AUTHZ_PATH" : 3 columns found
2018-09-11 22:34:13,670 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Check of existence of AUTHZ_PATHS_MAPPING returned no table
2018-09-11 22:34:13,670 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating table AUTHZ_PATHS_MAPPING
2018-09-11 22:34:13,670 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] CREATE TABLE AUTHZ_PATHS_MAPPING
(
AUTHZ_OBJ_ID BIGINT NOT NULL,
AUTHZ_OBJ_NAME VARCHAR(384) NOT NULL,
AUTHZ_SNAPSHOT_ID BIGINT NOT NULL,
CREATE_TIME_MS BIGINT NOT NULL
)
2018-09-11 22:34:13,696 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 26 ms
2018-09-11 22:34:13,697 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ALTER TABLE AUTHZ_PATHS_MAPPING ADD CONSTRAINT AUTHZ_PATHS_MAPPING_PK PRIMARY KEY (AUTHZ_OBJ_ID)
2018-09-11 22:34:13,733 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 36 ms
2018-09-11 22:34:13,759 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Loading column info for table(s) "AUTHZ_PATHS_SNAPSHOT_ID, AUTHZ_PATH, SENTRY_HMS_NOTIFICATION_ID, SENTRY_VERSION, AUTHZ_PATHS_MAPPING" in Catalog "", Schema ""
2018-09-11 22:34:13,905 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info loaded for Catalog "", Schema "", 5 tables, time = 146 ms
2018-09-11 22:34:13,906 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column info retrieved for table "AUTHZ_PATHS_MAPPING" : 4 columns found
2018-09-11 22:34:13,909 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating foreign key constraint : "AUTHZ_PATH_FK1" in catalog "" schema ""
2018-09-11 22:34:13,910 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ALTER TABLE AUTHZ_PATH ADD CONSTRAINT AUTHZ_PATH_FK1 FOREIGN KEY (AUTHZ_OBJ_ID) REFERENCES AUTHZ_PATHS_MAPPING (AUTHZ_OBJ_ID)
2018-09-11 22:34:13,972 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 62 ms
2018-09-11 22:34:13,973 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating index "AUTHZ_SNAPSHOT_ID_INDEX" in catalog "" schema ""
2018-09-11 22:34:13,973 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] CREATE INDEX AUTHZ_SNAPSHOT_ID_INDEX ON AUTHZ_PATHS_MAPPING (AUTHZ_SNAPSHOT_ID)
2018-09-11 22:34:14,081 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 108 ms
2018-09-11 22:34:14,084 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction committing with connection "com.jolbox.bonecp.ConnectionHandle@3f81621c"
2018-09-11 22:34:14,103 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Schema Transaction closing with connection "com.jolbox.bonecp.ConnectionHandle@3f81621c"
2018-09-11 22:34:14,103 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@abbe000 [conn=com.jolbox.bonecp.ConnectionHandle@3f81621c, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" is being committed.
2018-09-11 22:34:14,103 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@abbe000 [conn=com.jolbox.bonecp.ConnectionHandle@3f81621c, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" closed
2018-09-11 22:34:14,104 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating ValueGenerator instance of "org.datanucleus.store.rdbms.valuegenerator.TableGenerator" for "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping"
2018-09-11 22:34:14,104 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "SENTRY.SEQUENCE_TABLE.SEQUENCE_NAME" added to internal representation of table.
2018-09-11 22:34:14,104 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "SENTRY.SEQUENCE_TABLE.NEXT_VAL" added to internal representation of table.
2018-09-11 22:34:14,105 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@609e57da [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" opened with isolation level "read-committed" and auto-commit=false
2018-09-11 22:34:14,124 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Check of existence of SENTRY.SEQUENCE_TABLE returned table type of TABLE
2018-09-11 22:34:14,132 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@72eb6200"
2018-09-11 22:34:14,132 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT NEXT_VAL FROM SENTRY.SEQUENCE_TABLE WHERE SEQUENCE_NAME=<'org.apache.sentry.provider.db.service.model.MAuthzPathsMapping'> FOR UPDATE
2018-09-11 22:34:14,134 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 2 ms
2018-09-11 22:34:14,140 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@77fa9381"
2018-09-11 22:34:14,140 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT MAX(AUTHZ_OBJ_ID) FROM AUTHZ_PATHS_MAPPING
2018-09-11 22:34:14,141 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1 ms
2018-09-11 22:34:14,145 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2e32fc22" for connection "com.jolbox.bonecp.ConnectionHandle@33379242"
2018-09-11 22:34:14,146 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO SENTRY.SEQUENCE_TABLE (SEQUENCE_NAME,NEXT_VAL) VALUES (<'org.apache.sentry.provider.db.service.model.MAuthzPathsMapping'>,<6>)
2018-09-11 22:34:14,146 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2e32fc22"
2018-09-11 22:34:14,147 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2e32fc22"
2018-09-11 22:34:14,147 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@72bdd7c7"
2018-09-11 22:34:14,147 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@44fdce3c"
2018-09-11 22:34:14,147 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Reserved a block of 5 values
2018-09-11 22:34:14,148 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@609e57da [conn=com.jolbox.bonecp.ConnectionHandle@33379242, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" is being committed.
2018-09-11 22:34:14,153 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@609e57da [conn=com.jolbox.bonecp.ConnectionHandle@33379242, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" closed
2018-09-11 22:34:14,153 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Generated value for field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping (datastore id)" using strategy="custom" (Generator="org.datanucleus.store.rdbms.valuegenerator.TableGenerator") : value=1
2018-09-11 22:34:14,153 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" (id="1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") added to Level 1 cache (loadedFlags="[YYYY]")
2018-09-11 22:34:14,154 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" (id="1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") enlisted in transactional cache
2018-09-11 22:34:14,154 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" being inserted into table "AUTHZ_PATHS_MAPPING"
2018-09-11 22:34:14,154 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,154 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] BATCH [INSERT INTO AUTHZ_PATHS_SNAPSHOT_ID (AUTHZ_SNAPSHOT_ID) VALUES (<1>)]
2018-09-11 22:34:14,155 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1 ms (number of rows = [1]) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2b7e8044"
2018-09-11 22:34:14,166 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@16aed49f" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:14,167 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO AUTHZ_PATHS_MAPPING (AUTHZ_OBJ_ID,AUTHZ_OBJ_NAME,AUTHZ_SNAPSHOT_ID,CREATE_TIME_MS) VALUES (<1>,<'db1.table1'>,<1>,<1536723253400>)
2018-09-11 22:34:14,168 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@16aed49f"
2018-09-11 22:34:14,168 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Insert of object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" is calling insertPostProcessing for field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths"
2018-09-11 22:34:14,168 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@16aed49f"
2018-09-11 22:34:14,168 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Insert of object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" is calling postInsert for field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths"
2018-09-11 22:34:14,169 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths" is being persisted for "cascade-persist".
2018-09-11 22:34:14,193 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c"
2018-09-11 22:34:14,194 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Creating ValueGenerator instance of "org.datanucleus.store.rdbms.valuegenerator.TableGenerator" for "org.apache.sentry.provider.db.service.model.MPath"
2018-09-11 22:34:14,194 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "SENTRY.SEQUENCE_TABLE.SEQUENCE_NAME" added to internal representation of table.
2018-09-11 22:34:14,194 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Column "SENTRY.SEQUENCE_TABLE.NEXT_VAL" added to internal representation of table.
2018-09-11 22:34:14,195 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@fb49fdf [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" opened with isolation level "read-committed" and auto-commit=false
2018-09-11 22:34:14,196 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Check of existence of SENTRY.SEQUENCE_TABLE returned table type of TABLE
2018-09-11 22:34:14,197 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@753fd7a1"
2018-09-11 22:34:14,197 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT NEXT_VAL FROM SENTRY.SEQUENCE_TABLE WHERE SEQUENCE_NAME=<'org.apache.sentry.provider.db.service.model.MPath'> FOR UPDATE
2018-09-11 22:34:14,197 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0 ms
2018-09-11 22:34:14,204 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@6d091cad"
2018-09-11 22:34:14,205 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT MAX(PATH_ID) FROM AUTHZ_PATH
2018-09-11 22:34:14,205 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0 ms
2018-09-11 22:34:14,205 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@1e692555" for connection "com.jolbox.bonecp.ConnectionHandle@3bb5ceb"
2018-09-11 22:34:14,206 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO SENTRY.SEQUENCE_TABLE (SEQUENCE_NAME,NEXT_VAL) VALUES (<'org.apache.sentry.provider.db.service.model.MPath'>,<6>)
2018-09-11 22:34:14,206 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@1e692555"
2018-09-11 22:34:14,206 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@1e692555"
2018-09-11 22:34:14,207 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@76fe6cdc"
2018-09-11 22:34:14,207 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@786ff1cb"
2018-09-11 22:34:14,207 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Reserved a block of 5 values
2018-09-11 22:34:14,207 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@fb49fdf [conn=com.jolbox.bonecp.ConnectionHandle@3bb5ceb, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" is being committed.
2018-09-11 22:34:14,212 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@fb49fdf [conn=com.jolbox.bonecp.ConnectionHandle@3bb5ceb, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" closed
2018-09-11 22:34:14,213 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Generated value for field "org.apache.sentry.provider.db.service.model.MPath (datastore id)" using strategy="custom" (Generator="org.datanucleus.store.rdbms.valuegenerator.TableGenerator") : value=1
2018-09-11 22:34:14,213 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c" (id="1[OID]org.apache.sentry.provider.db.service.model.MPath") added to Level 1 cache (loadedFlags="[Y]")
2018-09-11 22:34:14,213 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c" (id="1[OID]org.apache.sentry.provider.db.service.model.MPath") enlisted in transactional cache
2018-09-11 22:34:14,214 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c" being inserted into table "AUTHZ_PATH"
2018-09-11 22:34:14,214 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,225 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5584d9c6" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:14,225 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO AUTHZ_PATH (PATH_ID,PATH_NAME,AUTHZ_OBJ_ID) VALUES (<1>,<'/user/hive/warehouse/db2.db/table1.1'>,<1>)
2018-09-11 22:34:14,228 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 3 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5584d9c6"
2018-09-11 22:34:14,229 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5584d9c6"
2018-09-11 22:34:14,229 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MPath@36b9cb99"
2018-09-11 22:34:14,229 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Generated value for field "org.apache.sentry.provider.db.service.model.MPath (datastore id)" using strategy="custom" (Generator="org.datanucleus.store.rdbms.valuegenerator.TableGenerator") : value=2
2018-09-11 22:34:14,230 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@36b9cb99" (id="2[OID]org.apache.sentry.provider.db.service.model.MPath") added to Level 1 cache (loadedFlags="[Y]")
2018-09-11 22:34:14,230 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@36b9cb99" (id="2[OID]org.apache.sentry.provider.db.service.model.MPath") enlisted in transactional cache
2018-09-11 22:34:14,230 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@36b9cb99" being inserted into table "AUTHZ_PATH"
2018-09-11 22:34:14,230 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,230 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2bfaba70" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:14,231 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO AUTHZ_PATH (PATH_ID,PATH_NAME,AUTHZ_OBJ_ID) VALUES (<2>,<'/user/hive/warehouse/db2.db/table1.2'>,<1>)
2018-09-11 22:34:14,248 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 17 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2bfaba70"
2018-09-11 22:34:14,248 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@2bfaba70"
2018-09-11 22:34:14,250 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" field "paths" is replaced by a SCO wrapper of type "org.datanucleus.store.types.wrappers.backed.HashSet" [cache-values=true, lazy-loading=true, allow-nulls=false]
2018-09-11 22:34:14,250 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" field "paths" is having its SCO wrapper initialised with a container with 2 values
2018-09-11 22:34:14,250 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672"
2018-09-11 22:34:14,251 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Generated value for field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping (datastore id)" using strategy="custom" (Generator="org.datanucleus.store.rdbms.valuegenerator.TableGenerator") : value=2
2018-09-11 22:34:14,251 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" (id="2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") added to Level 1 cache (loadedFlags="[YYYY]")
2018-09-11 22:34:14,251 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" (id="2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") enlisted in transactional cache
2018-09-11 22:34:14,252 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" being inserted into table "AUTHZ_PATHS_MAPPING"
2018-09-11 22:34:14,252 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,252 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@4ceff87d" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:14,252 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO AUTHZ_PATHS_MAPPING (AUTHZ_OBJ_ID,AUTHZ_OBJ_NAME,AUTHZ_SNAPSHOT_ID,CREATE_TIME_MS) VALUES (<2>,<'db1.table2'>,<1>,<1536723254250>)
2018-09-11 22:34:14,253 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@4ceff87d"
2018-09-11 22:34:14,253 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Insert of object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" is calling insertPostProcessing for field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths"
2018-09-11 22:34:14,253 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@4ceff87d"
2018-09-11 22:34:14,253 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Insert of object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" is calling postInsert for field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths"
2018-09-11 22:34:14,253 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths" is being persisted for "cascade-persist".
2018-09-11 22:34:14,253 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MPath@2c7db926"
2018-09-11 22:34:14,254 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Generated value for field "org.apache.sentry.provider.db.service.model.MPath (datastore id)" using strategy="custom" (Generator="org.datanucleus.store.rdbms.valuegenerator.TableGenerator") : value=3
2018-09-11 22:34:14,254 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@2c7db926" (id="3[OID]org.apache.sentry.provider.db.service.model.MPath") added to Level 1 cache (loadedFlags="[Y]")
2018-09-11 22:34:14,254 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@2c7db926" (id="3[OID]org.apache.sentry.provider.db.service.model.MPath") enlisted in transactional cache
2018-09-11 22:34:14,254 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@2c7db926" being inserted into table "AUTHZ_PATH"
2018-09-11 22:34:14,254 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,255 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@1668919e" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:14,255 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO AUTHZ_PATH (PATH_ID,PATH_NAME,AUTHZ_OBJ_ID) VALUES (<3>,<'/user/hive/warehouse/db2.db/table2.1'>,<2>)
2018-09-11 22:34:14,255 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@1668919e"
2018-09-11 22:34:14,256 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@1668919e"
2018-09-11 22:34:14,256 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Making object persistent : "org.apache.sentry.provider.db.service.model.MPath@22c53d82"
2018-09-11 22:34:14,256 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Generated value for field "org.apache.sentry.provider.db.service.model.MPath (datastore id)" using strategy="custom" (Generator="org.datanucleus.store.rdbms.valuegenerator.TableGenerator") : value=4
2018-09-11 22:34:14,256 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@22c53d82" (id="4[OID]org.apache.sentry.provider.db.service.model.MPath") added to Level 1 cache (loadedFlags="[Y]")
2018-09-11 22:34:14,256 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@22c53d82" (id="4[OID]org.apache.sentry.provider.db.service.model.MPath") enlisted in transactional cache
2018-09-11 22:34:14,257 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@22c53d82" being inserted into table "AUTHZ_PATH"
2018-09-11 22:34:14,257 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection found in the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,257 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@68d6d775" for connection "com.jolbox.bonecp.ConnectionHandle@5a49af50"
2018-09-11 22:34:14,257 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] INSERT INTO AUTHZ_PATH (PATH_ID,PATH_NAME,AUTHZ_OBJ_ID) VALUES (<4>,<'/user/hive/warehouse/db2.db/table2.2'>,<2>)
2018-09-11 22:34:14,261 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 4 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@68d6d775"
2018-09-11 22:34:14,262 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@68d6d775"
2018-09-11 22:34:14,262 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" field "paths" is replaced by a SCO wrapper of type "org.datanucleus.store.types.wrappers.backed.HashSet" [cache-values=true, lazy-loading=true, allow-nulls=false]
2018-09-11 22:34:14,262 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" field "paths" is having its SCO wrapper initialised with a container with 2 values
2018-09-11 22:34:14,262 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Transaction committing for ExecutionContext org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4
2018-09-11 22:34:14,262 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext.internalFlush() process started using ordered flush - 3 enlisted objects
2018-09-11 22:34:14,262 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext.internalFlush() process finished
2018-09-11 22:34:14,263 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing check of objects for "persistence-by-reachability" (commit) ...
2018-09-11 22:34:14,263 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing reachability algorithm on object with id "2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping"
2018-09-11 22:34:14,263 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" (id="2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") taken from Level 1 cache (loadedFlags="[YYYY]") [cache size = 8]
2018-09-11 22:34:14,263 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" (id="2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,263 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing reachability on multi-valued (collection/map) relation field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths"
2018-09-11 22:34:14,264 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@2c7db926" (id="3[OID]org.apache.sentry.provider.db.service.model.MPath") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@22c53d82" (id="4[OID]org.apache.sentry.provider.db.service.model.MPath") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing reachability algorithm on object with id "org.datanucleus.identity.IdentityReference@345cbf40"
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" (id="org.datanucleus.identity.IdentityReference@345cbf40") taken from Level 1 cache (loadedFlags="[Y]") [cache size = 8]
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" (id="org.datanucleus.identity.IdentityReference@345cbf40") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing reachability algorithm on object with id "1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping"
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" (id="1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") taken from Level 1 cache (loadedFlags="[YYYY]") [cache size = 8]
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" (id="1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,265 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing reachability on multi-valued (collection/map) relation field "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths"
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c" (id="1[OID]org.apache.sentry.provider.db.service.model.MPath") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@36b9cb99" (id="2[OID]org.apache.sentry.provider.db.service.model.MPath") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Performing reachability algorithm on object with id "1"
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" (id="org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId:1") taken from Level 1 cache (loadedFlags="[Y]") [cache size = 8]
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" (id="1") lifecycle state "P_NEW" added to the list of reachables on commit.
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext.internalFlush() process started using ordered flush - 0 enlisted objects
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext.internalFlush() process finished
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Completed check of objects for "persistence-by-reachability" (commit).
2018-09-11 22:34:14,266 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Committing [DataNucleus Transaction, ID=Xid= , enlisted resources=[org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@dd2856e]]
2018-09-11 22:34:14,267 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" committing for transaction "Xid= " with onePhase="true"
2018-09-11 22:34:14,267 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" closed
2018-09-11 22:34:14,268 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection removed from the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@56928e17 [conn=com.jolbox.bonecp.ConnectionHandle@5a49af50, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@f6de586]"
2018-09-11 22:34:14,269 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" (id="org.datanucleus.identity.IdentityReference@345cbf40") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,270 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d" (id="org.datanucleus.identity.IdentityReference@345cbf40") was evicted from transactional cache
2018-09-11 22:34:14,270 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" (id="org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId:1") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,270 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82" (id="org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId:1") was evicted from transactional cache
2018-09-11 22:34:14,271 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" (id="1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,271 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11" (id="1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") was evicted from transactional cache
2018-09-11 22:34:14,271 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c" (id="1[OID]org.apache.sentry.provider.db.service.model.MPath") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,271 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@5b5dce5c" (id="1[OID]org.apache.sentry.provider.db.service.model.MPath") was evicted from transactional cache
2018-09-11 22:34:14,271 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@36b9cb99" (id="2[OID]org.apache.sentry.provider.db.service.model.MPath") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@36b9cb99" (id="2[OID]org.apache.sentry.provider.db.service.model.MPath") was evicted from transactional cache
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" (id="2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672" (id="2[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping") was evicted from transactional cache
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@2c7db926" (id="3[OID]org.apache.sentry.provider.db.service.model.MPath") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@2c7db926" (id="3[OID]org.apache.sentry.provider.db.service.model.MPath") was evicted from transactional cache
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@22c53d82" (id="4[OID]org.apache.sentry.provider.db.service.model.MPath") has a lifecycle change : "P_NEW"->"HOLLOW"
2018-09-11 22:34:14,272 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Object "org.apache.sentry.provider.db.service.model.MPath@22c53d82" (id="4[OID]org.apache.sentry.provider.db.service.model.MPath") was evicted from transactional cache
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Transaction committed in 11 ms
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672 from StateManager[pc=org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@9301672, lifecycle=HOLLOW]
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82 from StateManager[pc=org.apache.sentry.provider.db.service.model.MAuthzPathsSnapshotId@40d23c82, lifecycle=HOLLOW]
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MPath@5b5dce5c from StateManager[pc=org.apache.sentry.provider.db.service.model.MPath@5b5dce5c, lifecycle=HOLLOW]
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MPath@22c53d82 from StateManager[pc=org.apache.sentry.provider.db.service.model.MPath@22c53d82, lifecycle=HOLLOW]
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MPath@2c7db926 from StateManager[pc=org.apache.sentry.provider.db.service.model.MPath@2c7db926, lifecycle=HOLLOW]
2018-09-11 22:34:14,273 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d from StateManager[pc=org.apache.sentry.provider.db.service.model.MSentryHmsNotification@3134153d, lifecycle=HOLLOW]
2018-09-11 22:34:14,274 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11 from StateManager[pc=org.apache.sentry.provider.db.service.model.MAuthzPathsMapping@2fd64b11, lifecycle=HOLLOW]
2018-09-11 22:34:14,274 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Disconnecting org.apache.sentry.provider.db.service.model.MPath@36b9cb99 from StateManager[pc=org.apache.sentry.provider.db.service.model.MPath@36b9cb99, lifecycle=HOLLOW]
2018-09-11 22:34:14,274 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Level 1 Cache cleared
2018-09-11 22:34:14,274 (main) [DEBUG - org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ExecutionContext "org.datanucleus.ExecutionContextThreadedImpl@21ac5eb4" closed
{code}
> Performance Issue: Saving MAuthzPathsMapping should be done in batch for path full snapshot
> -------------------------------------------------------------------------------------------
>
> Key: SENTRY-2185
> URL: https://issues.apache.org/jira/browse/SENTRY-2185
> Project: Sentry
> Issue Type: Bug
> Components: Sentry
> Affects Versions: 2.1.0
> Reporter: Na Li
> Assignee: Na Li
> Priority: Major
>
> From the code below, for each MAuthzPathsMapping, there is a query to save each MAuthzPathsMapping instance. Need to save the changes in batch.
> {code:java}
> public void persistFullPathsImage(final Map<String, Collection<String>> authzPaths,
> final long notificationID) throws Exception {
> tm.executeTransactionWithRetry(
> pm -> {
> pm.setDetachAllOnCommit(false); // No need to detach objects
> deleteNotificationsSince(pm, notificationID + 1);
> // persist the notidicationID
> pm.makePersistent(new MSentryHmsNotification(notificationID));
> // persist the full snapshot
> long snapshotID = getCurrentAuthzPathsSnapshotID(pm);
> long nextSnapshotID = snapshotID + 1;
> pm.makePersistent(new MAuthzPathsSnapshotId(nextSnapshotID));
> LOGGER.info("Attempting to commit new HMS snapshot with ID = {}", nextSnapshotID);
> for (Map.Entry<String, Collection<String>> authzPath : authzPaths.entrySet()) {
> pm.makePersistent(new MAuthzPathsMapping(nextSnapshotID, authzPath.getKey(), authzPath.getValue()));
> }
> return null;
> });
> }{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)