[midPoint] Approval performance issue : slow approverRef for orgs
Pavol Mederly
mederly at evolveum.com
Thu Oct 24 21:21:33 CEST 2019
Hello Fréderic,
it looks like your assigneeRef has an OID of null.
MidPoint should check that. (It does not, currently.) But you should not
give midPoint such strange assigneeRef. :-)
Best regards,
Pavol Mederly
Software developer
evolveum.com
On 24.10.2019 17:37, Frédéric Lohier wrote:
> 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
> <mailto: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 developer
> evolveum.com <http://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 <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/c36df4ec/attachment.htm>
More information about the midPoint
mailing list