[midPoint] Approval performance issue : slow approverRef for orgs
Pavol Mederly
mederly at evolveum.com
Fri Oct 25 18:06:47 CEST 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: <https://lists.evolveum.com/pipermail/midpoint/attachments/20191025/f73b5102/attachment.htm>
More information about the midPoint
mailing list