[midPoint] Approval performance issue : slow approverRef for orgs
Frédéric Lohier
frederic at lohier.org
Thu Oct 24 13:55:41 CEST 2019
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> 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 developerevolveum.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 listmidPoint at lists.evolveum.comhttp://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: <https://lists.evolveum.com/pipermail/midpoint/attachments/20191024/a6954818/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: midpoint-profile.zip
Type: application/zip
Size: 10831 bytes
Desc: not available
URL: <https://lists.evolveum.com/pipermail/midpoint/attachments/20191024/a6954818/attachment.zip>
More information about the midPoint
mailing list