[midPoint] Approval performance issue : slow approverRef for orgs

Pavol Mederly mederly at evolveum.com
Thu Oct 24 14:57:06 UTC 2019


Hello Fréderic,

good diagnostics!

getDeputyAssignees is a method that should return all users that are 
entitled to play the role of a deputy of given user (with regards to 
approvals).

It looks like it considered too many objects (26000+ users) when doing 
the search.

There are two possibilities:

 1. a bug in midPoint,
 2. some misconfiguration at your side.

Could you find an entry of call 2255172 (i.e. "Entry: 2255172" string) 
and tell me what arguments of searchObjects call are?

Then, have a look at any of the users returned, and look if it has 
"delegatedRef" filled in?

Best regards,

Pavol Mederly
Software developer
evolveum.com

On 24.10.2019 13:55, Frédéric Lohier wrote:
>
> Hello Pavol,
>
>
> Thank you for your input. I want further up in the profiling data (see 
> attached file) starting at the 
> ...model.impl.lens.Clockwork->authorizeRequest call which I guess is 
> the start of the authorization process for add the “suborg TEST” 
> organization.
>
> Then I get a bunch of “authorization 'authorization_name' in 
> dummy:00000000-0000-0000-0000-000000000000(Authorization_rolename) not 
> applicable for object because of” (from line 4 to 270) but my guess is 
> these are not an issue.
>
> Then the case “Approving and executing creation of organization 
> "suborg TEST"” is created (line 360), then I see 
> ...model.impl.controller.ModelInteractionServiceImpl->getDeputyAssignees# 
> (line 471) which might be culprit because shortly after that, I see :
>
> 2019-10-21 17:22:08,733 DEBUG: ##### Exit: 2255172 
> ...repo.sql.SqlRepositoryServiceImpl->searchObjects# etime: 16847.160 ms
>
> 2019-10-21 17:22:08,865 TRACE: ###### retval: 
> [user:00000000-0000-0000-0000-000000000000(name),user:00000000-0000-0000-0000-000000000000(name)...26000+ 
> users]
>
> which returned several thousands of user and lasted for more than 16 
> seconds, and shortly after that (line 809), again another
>
> 2019-10-21 17:22:15,333 DEBUG: ##### Exit: 2255170 
> ...repo.cache.RepositoryCache->searchObjects# etime: 23446.578 ms
>
> 2019-10-21 17:22:15,510 TRACE: ###### retval: 
> [user:00000000-0000-0000-0000-000000000000(name),user:00000000-0000-0000-0000-000000000000(name)...26000+ 
> users]
>
> Which lasted for more than 23 seconds. These 3 following lines seems 
> to confirm that the getDepyutyAssignees is the issue (lines 823 to 827) :
>
> 2019-10-21 17:22:16,907 DEBUG: ##### Exit: 2255169 
> ...model.api.ModelInteractionService->getDeputyAssignees etime: 
> 25021.556 ms
>
> 2019-10-21 17:22:16,908 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,908 DEBUG: ##### Exit: 2255168 
> ...model.impl.controller.ModelInteractionServiceImpl->getDeputyAssignees# 
> etime: 25021.792 ms
>
> 2019-10-21 17:22:16,908 TRACE: ###### retval: []
>
> 2019-10-21 17:22:16,908 DEBUG: ##### Exit: 2255165 
> ...wf.impl.engine.actions.OpenStageAction->execute etime: 25023.855 ms
>
> Is this getDeputyAssignees normal for an approveRef?
>
> -Frederic
>
>
> On Tue, Oct 22, 2019, 19:04 Pavol Mederly <mederly at evolveum.com 
> <mailto:mederly at evolveum.com>> wrote:
>
>     Hello Fréderic,
>
>     you are going in the right way. But you need to analyze the
>     profiling data in more depth. E.g. it looks like the most
>     interesting part is /before /the fragment you sent here.
>
>     Best regards,
>
>     Pavol Mederly
>     Software developer
>     evolveum.com  <http://evolveum.com>
>
>     On 22.10.2019 18:46, Frédéric Lohier wrote:
>>
>>     Hello,
>>
>>     I noticed a performance issue with approvals when the approverRef
>>     references a group of user (Org or Role) in a Midpoint instance
>>     with 20000+ users. My approvals are specified in a
>>     globalPolicyRule in the SystemConfiguration object.
>>
>>     When I specifies the approverRef as below, the approval request
>>     or the approval response each takes up to 30 seconds :
>>
>>     <approverRef oid="00000000-0000-0000-0000-000000000000"
>>     relation="org:default" type="c:OrgType">
>>
>>     Or
>>
>>     <approverRef type="OrgType">
>>
>>        <filter>
>>
>>     <q:equal>
>>
>>     <q:path>name</q:path>
>>
>>     <q:value>Name of the org</q:value>
>>
>>           </q:equal>
>>
>>        </filter>
>>
>>     <resolutionTime>run</resolutionTime>
>>
>>      </approverRef>
>>
>>     If I reduce the number of users in Midpoint, the approval
>>     request/response gets faster.
>>
>>     On the other hand, If I specify a static list of approverRef like :
>>
>>     <approverRef oid="00000000-0000-0000-0000-000000000000"
>>     type="c:UserType">
>>
>>     <approverRef oid="00000000-0000-0000-0000-000000000000"
>>     type="c:UserType">
>>
>>     Or a dynamic list of approvers through an approverExpression like :
>>
>>     <approverExpression>
>>
>>      <script>
>>
>>     <code>midpoint.getMembersAsReferences("00000000-0000-0000-0000-000000000000")</code>
>>
>>      </script>
>>
>>     </approverExpression>
>>
>>     Then , even with 20000+ users, the approval request/response
>>     takes less than a second to be processed.
>>
>>     For reference, the full global policy rule :
>>
>>     <globalPolicyRule>
>>
>>     <name>Delete user approvals</name>
>>
>>     <policyConstraints>
>>
>>     <modification>
>>
>>     <operation>delete</operation>
>>
>>     </modification>
>>
>>     </policyConstraints>
>>
>>     <policyActions>
>>
>>     <approval>
>>
>>     <approvalSchema>
>>
>>     <stage>
>>
>>     <approverRef oid="00000000-0000-0000-0000-000000000000"
>>     relation="org:default" type="c:OrgType">
>>
>>     <!-- Administrateurs Identités Arobas -->
>>
>>     </approverRef>
>>
>>                           <automaticallyCompleted>
>>
>>     <description>If the user has the superuser role, we automatically
>>     approve</description>
>>
>>     <script>
>>
>>     <code>
>>
>>                        if (midpoint.isDirectlyAssigned(actor,
>>     "00000000-0000-0000-0000-000000000004")) {
>>
>>     return 'skip';
>>
>>     }
>>
>>     else {
>>
>>                          return null;
>>
>>     }
>>
>>     </code>
>>
>>     </script>
>>
>>     </automaticallyCompleted>
>>
>>     </stage>
>>
>>     </approvalSchema>
>>
>>     </approval>
>>
>>     </policyActions>
>>
>>     <focusSelector>
>>
>>     <type>UserType</type>
>>
>>     </focusSelector>
>>
>>     </globalPolicyRule>
>>
>>     An excerpt of the trace:
>>
>>     2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255272
>>     ...repo.cache.RepositoryCache->getObject# etime: 1.311 ms
>>
>>     2019-10-21 17:22:16,948 TRACE: ###### retval:
>>     systemConfiguration:00000000-0000-0000-0000-000000000001(SystemConfiguration)
>>
>>     2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255271
>>     ...wf.impl.engine.helpers.NotificationHelper->sendPreparedNotifications
>>     etime: 1.755 ms
>>
>>     2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255257
>>     ...wf.impl.engine.EngineInvocationContext->commit etime: 40.146 ms
>>
>>     2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255157
>>     ...wf.impl.engine.WorkflowEngine->executeRequest etime: 25067.345 ms
>>
>>     2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255136
>>     ...wf.impl.processors.primary.PrimaryChangeProcessor->executeStartInstructions
>>     etime: 25146.234 ms
>>
>>     2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255118
>>     ...wf.impl.processors.primary.PrimaryChangeProcessor->previewOrProcessModelInvocation
>>     etime: 25153.706 ms
>>
>>     2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2255117
>>     ...wf.impl.hook.WfHook->invoke etime: 25153.876 ms
>>
>>     2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254939
>>     ...model.impl.lens.Clockwork->click etime: 25198.070 ms
>>
>>     2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,949 DEBUG: #### Entry: 2255276
>>     ...provisioning.impl.ProvisioningServiceImpl->exitConstraintsCheckerCache#
>>
>>     2019-10-21 17:22:16,949 TRACE: ###### args: ()
>>
>>     2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2255276
>>     ...provisioning.impl.ProvisioningServiceImpl->exitConstraintsCheckerCache#
>>     etime: 0.012 ms
>>
>>     2019-10-21 17:22:16,949 TRACE: ###### retval: null
>>
>>     2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254935
>>     ...model.impl.lens.Clockwork->run etime: 25198.487 ms
>>
>>     2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254934
>>     ...model.api.ModelService->executeChanges etime: 25198.728 ms
>>
>>     2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>>
>>     2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254933
>>     ...model.impl.controller.ModelController->executeChanges# etime:
>>     25201.841 ms
>>
>>
>>     _______________________________________________
>>     midPoint mailing list
>>     midPoint at lists.evolveum.com  <mailto:midPoint at lists.evolveum.com>
>>     http://lists.evolveum.com/mailman/listinfo/midpoint
>     _______________________________________________
>     midPoint mailing list
>     midPoint at lists.evolveum.com <mailto:midPoint at lists.evolveum.com>
>     http://lists.evolveum.com/mailman/listinfo/midpoint
>
>
> _______________________________________________
> midPoint mailing list
> midPoint at lists.evolveum.com
> http://lists.evolveum.com/mailman/listinfo/midpoint
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.evolveum.com/pipermail/midpoint/attachments/20191024/49dcd5df/attachment-0001.html>


More information about the midPoint mailing list