You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@sentry.apache.org by "Na Li (JIRA)" <ji...@apache.org> on 2018/03/19 21:11:00 UTC
[jira] [Commented] (SENTRY-2184) Performance Issue: MPath is
queried for each MAuthzPathsMapping in full snapshot
[ 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)