[midPoint] Approval performance issue : slow approverRef for orgs
Frédéric Lohier
frederic at lohier.org
Thu Oct 24 17:37:01 CEST 2019
Hello Pavol,
Thank you!
Here is the entry :
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255172
...repo.sql.SqlRepositoryServiceImpl->searchObjects#
2019-10-21 17:21:51,886 TRACE: ###### args: (UserType, Q{REF:
delegatedRef,,null paging, null,
R(com.evolveum.midpoint.repo.cache.RepositoryCache.searchObjects UNKNOWN
null))
For what it's worth, I have a read authorization on the delegatedRef item
of UserType.
-Frederic
On Thu, Oct 24, 2019, 16:57 Pavol Mederly <mederly at evolveum.com> wrote:
> 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 developerevolveum.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> 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
>>
>
> _______________________________________________
> 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/52162c01/attachment.htm>
More information about the midPoint
mailing list