[OPENIDM-14837] When a user has a large number of assignments, every additional assignment added takes an increasing length of time to process Created: 01/Jun/20  Updated: 23/Jul/20  Resolved: 23/Jul/20

Status: Closed
Project: OpenIDM
Component/s: Module - Relationships
Affects Version/s: 6.5.0, 7.0.0
Fix Version/s: 7.0.0, 6.5.0.4

Type: Bug Priority: Major
Reporter: Tom Wood Assignee: Chris Drake
Resolution: Fixed Votes: 1
Labels: release-notes
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive 48871 - Scripts.zip    
Issue Links:
Relates
relates to OPENIDM-15049 Delegated Admin failed privilege requ... Closed
is related to OPENIDM-14903 Do not process relationship derived v... Resolved
is related to OPENIDM-14900 Virtual properties are calculated inc... Closed
Target Version/s:
Verified Version/s:
QA Assignee: Alexander Dracka
Story Points: 3
Sprint: 2020.08 - IDM, 2020.09 - IDM
Support Ticket IDs:

 Description   

When adding an role and assignment to a user who already has a significant number of roles and assignments in place, each role and assignment added takes a longer period of time to process and return a result to the end-user.

To re-produce:

  • Install a base IDM 6.5.0 with a JDBC repo (Postgres used in my testing) using the sync-with-ldap-bidirectional sample
  • Add the following to the start and end of 'defaultMapping.js' to show process timing:
var start = new Date().getTime();



var end = new Date().getTime();
var time = end - start;
logger.info("defaultMappings took: " + time + "ms");
  • Download the attached scripts used to perform the testing (48871 - Scripts.zip)
  • Start IDM
  • Create a user within IDM and modify the 'addRoleMembers.sh' script with this user's _id
  • Within a terminal window run the following scripts in this order:
    • createRolesAndAssignmentsV2.sh
    • writeRoleIdToFile.sh
    • addRoleMembers.sh

While addRoleMembers.sh is running, you will see the output from cURL for each entry being added:

Processing role: Role141
{"_id":"5d9e27e2-83bf-4624-b754-2643afe1c8fb","_rev":"0","_ref":"managed/user/9c1bd995-ee2a-4648-aaae-09c21bd51ffc","_refResourceCollection":"managed/user","_refResourceId":"9c1bd995-ee2a-4648-aaae-09c21bd51ffc","_refProperties":{"_id":"5d9e27e2-83bf-4624-b754-2643afe1c8fb","_rev":"0"}}    time_namelookup:  0.004419
       time_connect:  0.004574
    time_appconnect:  0.013135
   time_pretransfer:  0.013154
      time_redirect:  0.000000
 time_starttransfer:  2.732836
                    ----------
         time_total:  2.732859

real	0m2.744s
user	0m0.009s
sys	0m0.005s

This can be correlated with the logging output added above to see the volume of time spent within the defaultMapping.js script.

Within my testing:

  • On 6.5.0, ~50-60% of the time taken at a higher number of roles was within the defaultMapping.js script
  • On 7.0.0 ~90% of the time taken at a higher number of roles was within the defaultMapping.js script. The non-script reduction is possibly due to OPENIDM-12527 and OPENIDM-10011.

In both cases above, the major time sink seems to be a loop around the script evaluation to perform the mergeWithTarget behaviour. This also occurs with replaceTarget to a lesser extent. This loop takes 15-20ms to occur for each role which is already in place which compounds as more roles are added.



 Comments   
Comment by Alexander Dracka [ 30/Jun/20 ]

Fixed
Verified with the OpenIDM version "7.0.0-SNAPSHOT" (build: 20200629200423, revision: f0fac87)

Processing role: Role499
{"_id":"25116262-62a4-4c43-b6dd-1556469c6e2d","_rev":"0","_ref":"managed/user/c78631fa-75a9-4d7f-adba-20509de1c6f2","_refResourceCollection":"managed/user","_refResourceId":"c78631fa-75a9-4d7f-adba-20509de1c6f2","_refProperties":{"_id":"25116262-62a4-4c43-b6dd-1556469c6e2d","_rev":"0"}}    time_namelookup:  0,004177
       time_connect:  0,004263
    time_appconnect:  0,000000
   time_pretransfer:  0,004294
      time_redirect:  0,000000
 time_starttransfer:  1,225094
                    ----------
         time_total:  1,225133

real	0m1,234s
user	0m0,003s
sys	0m0,006s

Comment by Lana Frost [ 23/Jul/20 ]

Reopening to add to release notes

Generated at Sat Mar 06 01:59:08 UTC 2021 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.