[midPoint] Approval performance issue : slow approverRef for orgs
Pavol Mederly
mederly at evolveum.com
Thu Oct 24 16:57:06 CEST 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: <https://lists.evolveum.com/pipermail/midpoint/attachments/20191024/49dcd5df/attachment.htm>
More information about the midPoint
mailing list