[midPoint] Approval performance issue : slow approverRef for orgs

Frédéric Lohier frederic at lohier.org
Fri Oct 25 15:17:50 UTC 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: <http://lists.evolveum.com/pipermail/midpoint/attachments/20191025/b562d397/attachment-0001.html>


More information about the midPoint mailing list