[
https://issues.apache.org/jira/browse/SENTRY-2184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16407227#comment-16407227
]
Na Li commented on SENTRY-2184:
-------------------------------
Removing "pm.getFetchPlan().setMaxFetchDepth(2);" does not make difference. As
long as the fetch groups are added to the pm, the MPath is fetched in bulk.
{code:java}
2018-03-20 17:38:33,568 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query :
Compiling "SELECT FROM
org.apache.sentry.provider.db.service.model.MAuthzPathsMapping WHERE
this.authzSnapshotID == currentSnapshotID PARAMETERS long currentSnapshotID"
for datastore
2018-03-20 17:38:33,664 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query :
Compile Time for datastore = 96 ms
2018-03-20 17:38:33,665 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT FROM
org.apache.sentry.provider.db.service.model.MAuthzPathsMapping WHERE
this.authzSnapshotID == currentSnapshotID PARAMETERS long currentSnapshotID
Query compiled to datastore query "SELECT
'org.apache.sentry.provider.db.service.model.MAuthzPathsMapping' AS
NUCLEUS_TYPE,A0.AUTHZ_OBJ_NAME,A0.AUTHZ_SNAPSHOT_ID,A0.CREATE_TIME_MS,A0.AUTHZ_OBJ_ID
FROM AUTHZ_PATHS_MAPPING A0 WHERE A0.AUTHZ_SNAPSHOT_ID = ?"
2018-03-20 17:38:33,666 (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-03-20 17:38:33,668 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] ManagedConnection
found in the pool :
"org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@6c8f60f3
[conn=com.jolbox.bonecp.ConnectionHandle@71b6172c, commitOnRelease=false,
closeOnRelease=false, closeOnTxnEnd=true]" for
key="org.datanucleus.ExecutionContextThreadedImpl@1174a305" in
factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@4d6ccc97]"
2018-03-20 17:38:33,670 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query :
Executing "SELECT FROM
org.apache.sentry.provider.db.service.model.MAuthzPathsMapping WHERE
this.authzSnapshotID == currentSnapshotID PARAMETERS long currentSnapshotID" ...
2018-03-20 17:38:33,751 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing
PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@7c0f28f8"
2018-03-20 17:38:33,753 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT
'org.apache.sentry.provider.db.service.model.MAuthzPathsMapping' AS
NUCLEUS_TYPE,A0.AUTHZ_OBJ_NAME,A0.AUTHZ_SNAPSHOT_ID,A0.CREATE_TIME_MS,A0.AUTHZ_OBJ_ID
FROM AUTHZ_PATHS_MAPPING A0 WHERE A0.AUTHZ_SNAPSHOT_ID = <1>
2018-03-20 17:38:33,756 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 4
ms
2018-03-20 17:38:33,760 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] >> JDOQL
Bulk-Fetch of
org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths
2018-03-20 17:38:33,910 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing
PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@511f5b1d"
2018-03-20 17:38:33,912 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT
'org.apache.sentry.provider.db.service.model.MPath' AS
NUCLEUS_TYPE,A0.PATH_NAME,A0.PATH_ID,A0.AUTHZ_OBJ_ID FROM AUTHZ_PATH A0 WHERE
EXISTS (SELECT 'org.apache.sentry.provider.db.service.model.MAuthzPathsMapping'
AS NUCLEUS_TYPE,A0_SUB.AUTHZ_OBJ_ID AS DN_DATASTOREID FROM AUTHZ_PATHS_MAPPING
A0_SUB WHERE A0_SUB.AUTHZ_SNAPSHOT_ID = <1> AND A0.AUTHZ_OBJ_ID =
A0_SUB.AUTHZ_OBJ_ID)
2018-03-20 17:38:33,916 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 5
ms
2018-03-20 17:38:33,918 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Retrieved object
with OID "1[OID]org.apache.sentry.provider.db.service.model.MAuthzPathsMapping"
{code}
> Performance Issue: MPath is queried for each MAuthzPathsMapping in full
> snapshot
> --------------------------------------------------------------------------------
>
> Key: SENTRY-2184
> URL: https://issues.apache.org/jira/browse/SENTRY-2184
> Project: Sentry
> Issue Type: Bug
> Components: Sentry
> Affects Versions: 2.1.0
> Reporter: Na Li
> Assignee: Na Li
> Priority: Critical
> Attachments: SENTRY-2184.001.patch
>
>
> MAuthzPathsMapping contains list of MPath instances. From log message, when
> getting path full snapshot at SentryStore.retrieveFullPathsImageCore(),
> DataNucleus issues a query for all MPath instances associated with each
> MAuthzPathsMapping. Therefore, getting full path image may take a very long
> time.
> The solution is to get MPath in a batch when getting full path image.
> Log Message when DataNucleus issues a query for all MPath instances
> associated with each MAuthzPathsMapping
> {code:java}
> 1) Initially, all MAuthzPathsMapping entries for current snapshot is queried.
> 2018-03-14 11:51:23,999 (main) [DEBUG -
> org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT
> 'org.apache.sentry.provider.db.service.model.MAuthzPathsMapping' AS
> NUCLEUS_TYPE,A0.AUTHZ_OBJ_NAME,A0.AUTHZ_SNAPSHOT_ID,A0.CREATE_TIME_MS,A0.AUTHZ_OBJ_ID
> FROM AUTHZ_PATHS_MAPPING A0 WHERE A0.AUTHZ_SNAPSHOT_ID = <1>
> 2) call authzToPaths.getPathStrings() causes MPath to be queried for each
> AUTHZ_OBJ_ID
> 2018-03-14 11:52:27,700 (main) [DEBUG -
> org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] SELECT
> 'org.apache.sentry.provider.db.service.model.MPath' AS
> NUCLEUS_TYPE,A0.PATH_NAME,A0.PATH_ID FROM AUTHZ_PATH A0 WHERE A0.AUTHZ_OBJ_ID
> = <1>{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
