Low Tested Environment
Crowd 3.1.1
Synchronized to Active Directory with approximately 16,000 users and 26,000 groups
Nested Group is Enabled
Database Cache is Enabled
Steps to Reproduce
- Connect the Active Directory with huge amount of users and groups to Crowd (Connector)
- Enable Nested Group
- Enable Database Cache
- Synchronize the Active Directory
- Click on Groups > Select any Group > Click on Direct Members tab
Expected Results
List of Groups in Group and Users in Group will display quickly if the result is less (E.g. only 2 groups in this group and no users at all)
Actual Results
It took approximately 20 seconds to return with the result of only 2 nested groups in this group and no users at all
Note
- It took about 20 seconds everytime tries to load the same tab. HAR file shows the time is waiting from Server
Time since last request Start Request Total Time Response Size Server HTTP Response X-AUSERNAME URL 0] 0s 2018-03-01T07:50:12.915Z 18652 ms 22.45 KB 200 OK
- Even with the Profiling turned on, not much information can be seen from the application logs. But there is a significant interval in the log that takes up to 11 seconds:
Time since last request Cumulative Interval Time Start Request 0] 0s 0s 2018-03-01 15:50:12,321 http-nio-8095-exec-2 DEBUG [2ms] 1] 0s 0s 2018-03-01 15:50:12,345 http-nio-8095-exec-2 DEBUG [23ms] 2] 0s 0s 2018-03-01 15:50:12,349 http-nio-8095-exec-2 DEBUG [4ms] 3] 0s 0s 2018-03-01 15:50:12,352 http-nio-8095-exec-2 DEBUG [1ms] 4] 0s 0s 2018-03-01 15:50:12,354 http-nio-8095-exec-2 DEBUG [1ms] 5] 0s 0s 2018-03-01 15:50:12,355 http-nio-8095-exec-2 DEBUG [1ms] 6] 0s 0s 2018-03-01 15:50:12,360 http-nio-8095-exec-2 DEBUG [3ms] 7] 0s 0s 2018-03-01 15:50:12,362 http-nio-8095-exec-2 DEBUG [1ms] 8] 0s 0s 2018-03-01 15:50:12,364 http-nio-8095-exec-2 DEBUG [1ms] 9] 1s 0s 2018-03-01 15:50:13,333 http-nio-8095-exec-2 DEBUG [969ms] 10] 1s 1s 2018-03-01 15:50:14,109 http-nio-8095-exec-2 DEBUG [184ms] 11] 0s 2s 2018-03-01 15:50:14,262 http-nio-8095-exec-2 DEBUG [153ms] 12] 0s 2s 2018-03-01 15:50:14,414 http-nio-8095-exec-2 DEBUG [152ms] 13] 0s 2s 2018-03-01 15:50:14,563 http-nio-8095-exec-2 DEBUG [148ms] 14] 0s 2s 2018-03-01 15:50:14,725 http-nio-8095-exec-2 DEBUG [162ms] 15] 0s 2s 2018-03-01 15:50:14,874 http-nio-8095-exec-2 DEBUG [148ms] 16] 1s 2s 2018-03-01 15:50:15,024 http-nio-8095-exec-2 DEBUG [150ms] 17] 0s 3s 2018-03-01 15:50:15,174 http-nio-8095-exec-2 DEBUG [149ms] 18] 0s 3s 2018-03-01 15:50:15,324 http-nio-8095-exec-2 DEBUG [150ms] 19] 0s 3s 2018-03-01 15:50:15,471 http-nio-8095-exec-2 DEBUG [147ms] 20] 0s 3s 2018-03-01 15:50:15,692 http-nio-8095-exec-2 DEBUG [221ms] 21] 0s 3s 2018-03-01 15:50:15,841 http-nio-8095-exec-2 DEBUG [148ms] 22] 0s 3s 2018-03-01 15:50:15,990 http-nio-8095-exec-2 DEBUG [149ms] 23] 1s 3s 2018-03-01 15:50:16,294 http-nio-8095-exec-2 DEBUG [150ms] 24] 0s 4s 2018-03-01 15:50:16,446 http-nio-8095-exec-2 DEBUG [152ms] 25] 0s 4s 2018-03-01 15:50:16,601 http-nio-8095-exec-2 DEBUG [154ms] 26] 0s 4s 2018-03-01 15:50:16,826 http-nio-8095-exec-2 DEBUG [148ms] 27] 0s 4s 2018-03-01 15:50:16,975 http-nio-8095-exec-2 DEBUG [149ms] 28] 1s 4s 2018-03-01 15:50:17,127 http-nio-8095-exec-2 DEBUG [151ms] 29] 11s 5s 2018-03-01 15:50:28,840 http-nio-8095-exec-2 DEBUG [147ms] 30] 0s 16s 2018-03-01 15:50:28,989 http-nio-8095-exec-2 DEBUG [149ms] 31] 1s 16s 2018-03-01 15:50:29,139 http-nio-8095-exec-2 DEBUG [150ms] 32] 0s 17s 2018-03-01 15:50:29,626 http-nio-8095-exec-2 DEBUG [154ms] 33] 0s 17s 2018-03-01 15:50:29,784 http-nio-8095-exec-2 DEBUG [156ms] 34] 0s 17s 2018-03-01 15:50:29,952 http-nio-8095-exec-2 DEBUG [167ms] 35] 1s 17s 2018-03-01 15:50:30,106 http-nio-8095-exec-2 DEBUG [153ms] 36] 0s 18s 2018-03-01 15:50:30,262 http-nio-8095-exec-2 DEBUG [156ms] 37] 0s 18s 2018-03-01 15:50:30,417 http-nio-8095-exec-2 DEBUG [155ms] 38] 0s 18s 2018-03-01 15:50:30,571 http-nio-8095-exec-2 DEBUG [151ms] 39] 0s 18s 2018-03-01 15:50:30,798 http-nio-8095-exec-2 DEBUG [227ms] 40] 0s 18s 2018-03-01 15:50:30,952 http-nio-8095-exec-2 DEBUG [154ms] Total lines : 41 Longest interval between lines : 11s Time from first line to last line: 18s
- Same goes to SQL Logging enabled, it is still unclear what is taking the 11 seconds:
Hibernate: select this_.id as id1_29_0_, this_.user_name as user_name2_29_0_, this_.lower_user_name as lower_user_name3_29_0_, this_.active as active4_29_0_, this_.created_date as created_date5_29_0_, this_.updated_date as updated_date6_29_0_, this_.first_name as first_name7_29_0_, this_.lower_first_name as lower_first_name8_29_0_, this_.last_name as last_name9_29_0_, this_.lower_last_name as lower_last_name10_29_0_, this_.display_name as display_name11_29_0_, this_.lower_display_name as lower_display_nam12_29_0_, this_.email_address as email_address13_29_0_, this_.lower_email_address as lower_email_addre14_29_0_, this_.external_id as external_id15_29_0_, this_.directory_id as directory_id16_29_0_, this_.credential as credential17_29_0_ from cwd_user this_ where this_.directory_id=? and this_.lower_user_name=? 2018-03-01 15:50:16,975 http-nio-8095-exec-2 DEBUG [atlassian.util.profiling.UtilTimerStack] [149ms] - ApplicationService.findUserByName() [0ms] - AliasManager.findUsernameByAlias() [74ms] - ApplicationService.findUserByName() [74ms] - ApplicationService.findUserByName() [73ms] - DirectoryManager.findUserByName() [0ms] - AliasManager.findAliasByUsername() Hibernate: select this_.ID as ID1_20_0_, this_.created_date as created_date2_20_0_, this_.permission_id as permission_id3_20_0_, this_.app_dir_mapping_id as app_dir_mapping_id4_20_0_, this_.group_name as group_name5_20_0_ from cwd_granted_perm this_ where this_.permission_id=? Hibernate: select this_.ID as ID1_20_0_, this_.created_date as created_date2_20_0_, this_.permission_id as permission_id3_20_0_, this_.app_dir_mapping_id as app_dir_mapping_id4_20_0_, this_.group_name as group_name5_20_0_ from cwd_granted_perm this_ where this_.permission_id=? Hibernate: select this_.id as id1_23_0_, this_.parent_id as parent_id2_23_0_, this_.child_id as child_id3_23_0_, this_.membership_type as membership_type4_23_0_, this_.group_type as group_type5_23_0_, this_.parent_name as parent_name6_23_0_, this_.lower_parent_name as lower_parent_name7_23_0_, this_.child_name as child_name8_23_0_, this_.lower_child_name as lower_child_name9_23_0_, this_.created_date as created_date10_23_0_, this_.directory_id as directory_id11_23_0_ from cwd_membership this_ where this_.directory_id=? and this_.lower_parent_name=? and this_.lower_child_name=? and this_.membership_type=? 2018-03-01 15:50:17,127 http-nio-8095-exec-2 DEBUG [atlassian.util.profiling.UtilTimerStack] [151ms] - UserPermissionService.hasPermission() [149ms] - DirectoryManager.isUserNestedGroupMember() ***************** 11 second gap ***************** Hibernate: select applicatio0_.id as id1_4_, applicatio0_.application_name as application_name2_4_, applicatio0_.lower_application_name as lower_application_3_4_, applicatio0_.created_date as created_date4_4_, applicatio0_.updated_date as updated_date5_4_, applicatio0_.active as active6_4_, applicatio0_.description as description7_4_, applicatio0_.application_type as application_type8_4_, applicatio0_.credential as credential9_4_ from cwd_application applicatio0_ where applicatio0_.application_type=? order by applicatio0_.lower_application_name 2018-03-01 15:50:28,840 http-nio-8095-exec-2 DEBUG [atlassian.util.profiling.UtilTimerStack] [147ms] - ApplicationManager.search()
- Thread and CPU Dump taken and the result as below:
- During the 11 seconds, CPU usage is almost always near to 100% and the thread dumps tell us:
- There are no JDBC calls in the Thread Dump so any call to the database is already done and completed.
- Looking at the Profiling times, any calls to the database are really fast as well
- It looks like it's spending all it's time doing Hibernate things
"http-nio-8095-exec-2" #91 daemon prio=5 os_prio=0 tid=0x00007f0088473000 nid=0x28a8 runnable [0x00007effdabd5000] java.lang.Thread.State: RUNNABLE at org.hibernate.event.internal.AbstractVisitor.processValue(AbstractVisitor.java:102) at org.hibernate.event.internal.WrapVisitor.processValue(WrapVisitor.java:108) at org.hibernate.event.internal.AbstractVisitor.processEntityPropertyValues(AbstractVisitor.java:59) at org.hibernate.event.internal.DefaultFlushEntityEventListener.wrapCollections(DefaultFlushEntityEventListener.java:203) at org.hibernate.event.internal.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:140) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:216) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:85) at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:38) ...
Thread ID Number of files that % CPU Busy File # CPU file name Thread file name - experimental Thread ID appears in ---------------- -------------------- ---------- ------ ----------------------------------- ----------------------------------- 10408 (0x28a8) : 7 file(s) :: [ 98.5 | 1 | top-2018-03-01_15-50-14.txt] app_threads.20180301_155014.txt - http-nio-8095-exec-2 (nid=0x28a8) [ 98.5 | 2 | top-2018-03-01_15-50-17.txt] app_threads.20180301_155017.txt [ 100 | 3 | top-2018-03-01_15-50-19.txt] app_threads.20180301_155019.txt [ 100 | 4 | top-2018-03-01_15-50-22.txt] app_threads.20180301_155022.txt [ 98.5 | 5 | top-2018-03-01_15-50-24.txt] app_threads.20180301_155024.txt [ 98.5 | 6 | top-2018-03-01_15-50-27.txt] app_threads.20180301_155027.txt [ 98.4 | 7 | top-2018-03-01_15-50-29.txt] app_threads.20180301_155029.txt
- During the 11 seconds, CPU usage is almost always near to 100% and the thread dumps tell us:
Findings from Developer
- The time to load this view grows linearly to amount of groups within the directory
- Expected to have the fix released in Crowd 3.1.3
- is duplicated by
-
KRAK-1202 Loading...