Confluence 5.9+ much slower to sync users and remove users from groups compared to 5.8

Problem summary

In comparison to Confluence 5.8.x (and possibly earlier versions), Confluence 5.9.x and 5.10.x is much slower at the following events as part of an LDAP Connector directory sync. These are two of the events that are part of UserIndexingListener.java:

• Pulling in large numbers of new users ("onUserAddEvent" in both 5.8 and 5.9+)
• Removing larger numbers of users from a group ("onMembershipDeletedEvent", added in 5.9+).

Steps to reproduce the slow "onUserAddEvent"

As this is a bug report for a performance regression, we must compare 5.8 performance with later versions by carrying out the same steps:

1. Create an LDAP server with a significant amount of users. The one I used contained 50k, for reference.
2. Add these users into a single LDAP group
3. In Confluence, navigate to Confluence Admin > Logging & Profiling and set package "com.atlassian.confluence.user.crowd" to DEBUG
4. In Confluence, navigate to Confluence Admin > User Directories and create a new user LDAP or AD user directory
5. Configure directory to be able to see all of the users and the one group
6. Save the directory, which will begin the sync
7. Tail the logs and look for the "onUserAddEvent" event, e.g.:

   ...
   2017-01-05 19:40:20,346 DEBUG [scheduler_Worker-1] [confluence.user.crowd.UserIndexingListener] onUserAddEvent User added: example_user_1
   2017-01-05 19:40:20,718 DEBUG [scheduler_Worker-1] [confluence.user.crowd.UserIndexingListener] onUserAddEvent User added: example_user_2
   ...
   

Steps to reproduce the slow "onMembershipDeletedEvent"

1. In a 5.9+ environment, first go through the above steps to sync a large number of users and one group
2. After the on the LDAP side, remove all users from the group
3. In the Confluence UI, sync again
4. Tail the logs and look for the "onMembershipDeletedEvent"

Performance comparisons between versions

• In Confluence 5.8.18, about 80-100 of the "onUserAddEvent" records would be printed per second, reflecting the rate of users being added. The rate of processing appears to be consistent and does not slow down. "onMembershipDeletedEvent" does not appear at all in 5.8 (but users are still removed from group as expected).
• In Confluence 5.9.12 or 5.10.8, the "onUserAddEvent" and "onMembershipDeletedEvent" both start out relatively fast at 50 users per second, before quickly dwindling down to 15 per second, 8 per second, 3 per second, etc. This has a significant impact on overall directory sync duration. During this time the User Directory UI will show "Adding X users to the cache" and "Removing X users from group", respectively.

One can also use the command below to quickly see how many user records are processed per second on each event, by parsing Confluence logs:

grep 'onUserAddEvent' /path/to/confluence/logs/atlassian-confluence.log | cut -c 1-19 | uniq -c

grep 'onMembershipDeletedEvent' /path/to/confluence/logs/atlassian-confluence.log | cut -c 1-19 | uniq -c

Output will look like the below, grouped by each second. The first line, for example, indicates that during the 19:48:00 second, just 2 instances of "onUserAddEvent" were recorded:

   2 2017-01-05 19:48:00
   3 2017-01-05 19:48:01
   2 2017-01-05 19:48:02
   2 2017-01-05 19:48:03

Notes

• I do not suspect this to be a problem with underlying Crowd libraries, rather how Confluence processes new users. Hence, this bug is not filed against Crowd.
• This is not related to the 5.10 audit logging feature, as the problem can be reproduced in 5.9
• This is possibly related (but not confirmed) to Embedded Crowd versions between each application, or an issue within Confluence itself. See table below

  Confluence version	Crowd library version	Embedded Crowd library version	User processing speed
  5.8.18	2.8.3	1.8.1	Fast
  5.9.12	2.8.3	2.0.1	Slow
  5.10.8	2.8.8	2.0.1	Slow