[midPoint] Approval performance issue : slow approverRef for orgs
Frédéric Lohier
frederic at lohier.org
Fri Oct 25 18:33:12 CEST 2019
Hello Pavol,
For now, my issue is fixed by using the onWorkItemCreation expansion.
I will create the jira issue on Monday.
Thank you for your help and have a nice weekend!
-Frederic
On Fri, Oct 25, 2019, 18:06 Pavol Mederly <mederly at evolveum.com> wrote:
> 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 developerevolveum.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> 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
>>
>
> _______________________________________________
> 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/5079029e/attachment.htm>
More information about the midPoint
mailing list