[midPoint] Approval performance issue : slow approverRef for orgs
Frédéric Lohier
frederic at lohier.org
Fri Oct 25 17:17:50 CEST 2019
Hello Pavol,
I if understood correctly, the AssigneeRef attribute is only attached to a
workItem (which is part of a Case), and all the members of the ApproverRef
Org or Role that I specified in the GlobalPolicyRule should be mentionned
as assigneeRef in their approval workItem, right?
So, for example, if I have an approverRef like
<approverRef oid="00000000-0000-0000-0000-000000000000"
relation="org:default" type="c:OrgType" />
Each member of Org 00000000-0000-0000-0000-000000000000 are assigneeRef of
their workItem in the “adding user” case if I choose
<groupExpansion>onWorkItemCreation</groupExpansion> in the approval stage.
But if I choose <groupExpansion>byClaimingWorkItem</groupExpansion>, there
is no assigneeRef and the workitem since each member of the “approval
group” needs to claim the workitem.
I tested again, and
<stage>
<approverRef oid="00000000-0000-0000-0000-000000000000"
relation="org:default" type="c:OrgType" />
<evaluationStrategy>firstDecides</evaluationStrategy>
<outcomeIfNoApprovers>reject</outcomeIfNoApprovers>
<groupExpansion>*onWorkItemCreation*</groupExpansion>
</stage>
works well (fast processing of the approval workitem), but if I switch
groupExpansion to *byClaimingWorkItem*, then I get the issue of slow
approval request workitem.
By the way, none of my test users have a delegatedRef and I use the latest
Midpoint 4.0.1-SNAPSHOT for my tests.
On Thu, Oct 24, 2019, 21:21 Pavol Mederly <mederly at evolveum.com> wrote:
> 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 developerevolveum.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> 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
>>
>
> _______________________________________________
> 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/20191025/b562d397/attachment.htm>
More information about the midPoint
mailing list