[
https://issues.apache.org/jira/browse/SENTRY-2184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16405454#comment-16405454
]
Na Li commented on SENTRY-2184:
-------------------------------
1) We can use fetch group to bulk-fetch the MPath and save multiple round trip
time between sentry server and DB
[http://www.datanucleus.org/products/accessplatform_3_2/jdo/fetchgroup.html]
2) The log message when DataNucleus issues bulk-fetch for MPath
{code:java}
2018-03-19 11:30:15,627 (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"
2018-03-19 11:30:15,628 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query :
Compile Time = 1 ms
2018-03-19 11:30:15,629 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] QueryCompilation:
[filter:DyadicExpression{PrimaryExpression{this.authzSnapshotID} =
ParameterExpression{currentSnapshotID}}]
[symbols: currentSnapshotID type=long, this
type=org.apache.sentry.provider.db.service.model.MAuthzPathsMapping]
2018-03-19 11:30:15,629 (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-19 11:30:15,631 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] You have selected
field org.apache.sentry.provider.db.service.model.MAuthzPathsMapping.paths for
fetching by this query. We will fetch it using bulk-fetch. To disable this set
the query extension/hint 'datanucleus.multivaluedFetch' as 'none' or remove the
field from the query FetchPlan. If this bulk-fetch generates an invalid or
unoptimised query, please report it with a way of reproducing it
2018-03-19 11:30:15,641 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] JDOQL Query :
Compile Time for datastore = 12 ms
2018-03-19 11:30:15,641 (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-19 11:30:15,642 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Not caching the
datastore compilation since some parameters are evaluated during the
compilation and aren't present in the final datastore-specific query
2018-03-19 11:30:15,642 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Connection found
in the pool :
org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@697173d9
[conn=com.jolbox.bonecp.ConnectionHandle@5f174dd2, commitOnRelease=false,
closeOnRelease=false, closeOnTxnEnd=true] for
key=org.datanucleus.ExecutionContextThreadedImpl@4ca8dbfa in
factory=ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@363c4251]
2018-03-19 11:30:15,642 (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-19 11:30:15,654 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing
PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@2740e316"
2018-03-19 11:30:15,654 (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-19 11:30:15,654 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 0
ms
2018-03-19 11:30:15,655 (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-19 11:30:15,668 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Closing
PreparedStatement "com.jolbox.bonecp.PreparedStatementHandle@53e76c11"
2018-03-19 11:30:15,669 (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-19 11:30:15,669 (main) [DEBUG -
org.datanucleus.util.Log4JLogger.debug(Log4JLogger.java:58)] Execution Time = 1
ms{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)
