[OPENIDM-5465] Performance Issue updating conditional role memberships Created: 18/Mar/16  Updated: 31/Jul/18  Resolved: 31/Jul/18

Status: Closed
Project: OpenIDM
Component/s: Module - Roles, Performance
Affects Version/s: OpenIDM 4.5.0, OpenIDM 5.0.0
Fix Version/s: 6.5.0

Type: Bug Priority: Major
Reporter: Dirk Hogan Assignee: Jenny Zhang
Resolution: Fixed Votes: 2
Labels: CLARK, Performance, release-notes
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: HTML File conditional_roles_smartevent_log    
Issue Links:
Backport
is backported by OPENIDM-11167 Backport OPENIDM-5465: Performance Is... Closed
Relates
relates to OPENIDM-5470 Managed user creation with POST timeo... Closed
is related to OPENIDM-5816 Performance issue with basic provisio... Closed
Target Version/s:
Story Points: 5
Sprint: OpenIDM Sprint 60
Support Ticket IDs:

 Description   

While investigating OPENIDM-5415, I noticed major latencies when updating ~70 conditional roles in a repo with 1000 users. The calculations performed by conditionalRoles.updateRole would result in populating a role members array with ~35 managed user instances - the ~35 managed users who were granted the role prior to the update were not present in the array, and the new grantees are present, for a diff total of ~70. The calculations performed by conditionalRoles.updateRole to generate the updated role membership array takes ~1 second. The processing of these updates in ManagedObjectSet#update took up to several minutes. The offending invocations made from ManagedObjectSet#update are validateRelationshipFields(line 485) and persistRelationships (line 506). Both can take >30 seconds to return.

To reproduce:
1.Create a repo with 1000 users using Huck's resource creator.
2.Create a conditional role with a condition like "mail sw 'a'".
3.Update this role condition to look for a different character - e.g. b.

The really slow latencies are not always observable - usually it is only 'somewhat' slow - i.e. 7-15 seconds - but still seemingly beyond of expected latencies when updating ~100 records.



 Comments   
Comment by Lana Frost [ 30/Jun/16 ]

Adding this one to the Release Notes. Note though that we do describe this performance limitation in the Conditional Role docs:
https://forgerock.org/openidm/doc/bootstrap/integrators-guide/#conditional-role-grants

Comment by Dirk Hogan [ 19/Oct/16 ]

Changing target version to 5.5. There is not sufficient time to investigate/address fully prior to the 5.0 release.

Comment by Andy Itter [ 18/Jan/17 ]

Test using an OOTB OpenIDM 4.5:

  • Created 1000 managed users
  • Created a role in the UI with a condition that matched all the users (eg. mail is equal to 'shared mail address') and clicked Save
  • The request returned in 146135ms (2.4 mins) according to the browser debugger

Ran the same test using a current 5.0 snapshot:

  • The task completed in 164592ms

Note that in a scenario with over 100K users this task takes over 20 minutes.

Comment by Jon Branch [ 05/Apr/18 ]

Dirk Hogan Is this still an issue following all the recent improvements?

Comment by Dirk Hogan [ 12/Apr/18 ]

Results of running this test against the 6.0 code-base: creating a role with a condition which applied to 10,001 users took ~183 seconds on my laptop(embedded DJ and no mappings - bare ./startup.sh with no -p) and 253 seconds with mysql with mappings(sync-with-ldap-bidirectional sample). This seems to be a very significant improvement on the 5.0 code-base, which took ~164 seconds for 1000 users. 

Note that when a conditional role is created:

  1. all users which match this condition must be queried
  2. the role must be updated with all users from #1
  3. a relationship from the role to the users from #2 must be written to the repo
  4. the referred-to managed users in #3 must be signaled so that a sync check can be performed and the onUpdate script run for each of the managed users.

All this takes some time. That being said, I think the signaling logic prior to the 6.0 refactor generated many superfluous actions.

Andy Itter, if this is still an issue, can you run your test against the 6.0 bits to see if your results improve? I would expect they would be substantially better. The work done in 1-4 cannot be changed. As mentioned above, however, the logic in conditionalRoles#roleCreated could be moved into java, thereby allowing actions 2-4 to be done concurrently. This would result in significant latency improvements. Pulling the logic in conditionalRoles.js back into java is very-much desired; when the work is done is simply a question of priorities.  

 

Comment by Jenny Zhang [ 28/Apr/18 ]

With today's 6.5.0-SNAPSHOT,
I had 80 managed users, creating 1 conditional role, time is 3.7 sec
Then preload the database with 100 users + 80 managers, creating 1 conditional role, time is 17.572 sec

Created a pyforge test for this for driving the workload.
Will debug more

Comment by Jenny Zhang [ 03/May/18 ]

preload the database with 85 managers and 300 managed users, each user has 5 roles. Creating a conditional role that covers the email addresses of all the users takes 67sec.

Call count:

method namd call count comment
openidm.managed.ManagedObjectSet.createInstance 1 create 1 conditional role
openidm.managed.VertexToEdgeSignaller.createAssociatedEdges 1
openidm.managed.edge.EdgeCollectionHandler.createEdge 385 createEdges for 385 objects
openidm.managed.EdgeToVertexActionHandler.relationshipCreated 385
openidm.managed.ManagedObjectSet.handleSignalVertexUpdateFromEdge 385
openidm.managed.ManagedObjectSet.populateVirtualProperties 771 old and new vertex state
openidm/bin/defaults/script/roles/effectiveAssignments.js 1155 771 for populate virtual properties, 385 for validate relationship
rhino script from openidm.managed.SchemaField.onRetrieve 104303 70% for populate virtual properties 30% for validate relationship

Wall time:

method namd wall time comment
openidm.managed.ManagedObjectSet.createInstance 83668 Entry point
->openidm.managed.VertexToEdgeSignaller.createAssociatedEdges 65609
-->openidm.managed.ManagedObjectSet.populateVirtualProperties 21772 new value
-->openidm.managed.ManagedObjectSet.populateVirtualProperties 21772 old value
-->openidm.managed.ManagedObjectSet.execScriptHook 10438
->openidm.managed.ManagedObjectSet.validateRelationshipFields 18009
-->openidm.managed.SchemaField.onRetrieve 16959
Comment by Jenny Zhang [ 03/May/18 ]

based on the wall time numbers, most of the time is spent on populate old/new virtualProperties for edges.
With final build 6.0.0 the time is 65435ms
With 6.5-snapshot, the time is 46876ms
Those 2 methods mostly execute rhino scripts.
So https://stash.forgerock.org/projects/OPENIDM/repos/openidm/pull-requests/3919/overview did help, as the number of opened files reduced from 29,173 to 769

But even with 6.5.0-SNAPSHOT, there are following issues:
openidm/bin/defaults/script/roles/effectiveAssignments.js is read multiple (719) times. Should this be cached?

[Exception] Path="/Users/jenny.zhang/work/pyforge/pyforge/results/20180503-132931/relationship/openidm1/openidm/script/lib/lodash.js"
[Exception] Path="/Users/jenny.zhang/work/pyforge/pyforge/results/20180503-132931/relationship/openidm1/openidm/script/roles/relationshipHelper.js"
[Exception] Path="/Users/jenny.zhang/work/pyforge/pyforge/results/20180503-132931/relationship/openidm1/openidm/script/roles/conditionalRoles.js"
[Exception] Path="/Users/jenny.zhang/work/pyforge/pyforge/results/20180503-132931/relationship/openidm1/openidm/script/roles/conditionalRoles.js" [Exception] Path="/Users/jenny.zhang/work/pyforge/pyforge/results/20180503-132931/relationship/openidm1/openidm/roles/effectiveRoles"
[Exception] Path="/Users/jenny.zhang/work/pyforge/pyforge/results/20180503-132931/relationship/openidm1/openidm/script/roles/postOperation-roles.js"

770 read from /dev/urandom should this be cached

Comment by Dirk Hogan [ 03/May/18 ]

Ha - that is a great find Jenny Zhang!! And it somewhat restores my belief that I know what high-latency actions are.

Comment by Jenny Zhang [ 03/May/18 ]

Another issue is jdbc statement we executed.
Call stack
com.mysql.jdbc.PreparedStatement.executeUpdate() PreparedStatement.java
com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate() ProxyPreparedStatement.java:61
com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate() HikariProxyPreparedStatement.java
org.forgerock.openidm.repo.jdbc.impl.query.TracedPreparedStatement.executeUpdate() TracedPreparedStatement.java:83
org.forgerock.openidm.repo.jdbc.impl.GenericTableHandler.create(Context, String, String, String, JsonValue, Connection) GenericTableHandler.java:348
org.forgerock.openidm.repo.jdbc.impl.JDBCRepoService.handleCreate(Context, CreateRequest) JDBCRepoService.java:348

number of prepared statemets 19,479
All this work is done by 1 worker thread

Generated at Mon Dec 17 08:18:03 GMT 2018 using JIRA 7.3.8#73019-sha1:94e8771b8094eef96c119ec22b8e8868d286fa88.