[midPoint] Approval performance issue : slow approverRef for orgs

Pavol Mederly mederly at evolveum.com
Fri Oct 25 16:06:47 UTC 2019


Hello Fréderic,

when using *byClaimingWorkItem *expansion, there is a single work item 
created, with no assigneeRef, but a *candidateRef* pointing to the Org. 
This is the expected behavior. At least if I am not seriously mistaken. :)

In contrast, when using *onWorkItemCreation* expansion, a single work 
item is created *for each* Org member; with *assigneeRef* pointing to 
that member.

---

So I'd recommend to use "onWorkItemCreation". The other part 
(byClaimingWorkItem) has - besides this issue - some other, less 
serious, problems in GUI; like candidates not correctly shown, etc.

---

You can create a JIRA issue for this, describing the situation. I cannot 
promise to fix it now (or in any given moment), but it helps us to track 
the it.

Best regards,

Pavol Mederly
Software developer
evolveum.com

On 25.10.2019 17:17, Frédéric Lohier wrote:
>
> 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 
> <mailto: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 developer
>     evolveum.com  <http://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  <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: <http://lists.evolveum.com/pipermail/midpoint/attachments/20191025/f73b5102/attachment-0001.html>


More information about the midPoint mailing list