[
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)
