[User Profiles for Confluence] Slow performance by User Profile Macro

Błażej O_

Hi,

We are evaluating User Profiles for Confluence. We have noticed that User Profile Macro causes slow loading of confluence pages. Single user profile adds around 0,3-0,4 overhead to the page loading time. It became a problem when we have tried to open one of our department structure sites with 110+ user profile macros. This site loads in less then 2 seconds on default system profile macro. On Communardo's profile macro it takes 29-33 seconds to load...

I have created a page with only one profile macro, and compared it to the blank site with profiling.

On blank site the "XW View: doExecute(/pages/viewpage.vm)" action goes immediately after "XW Interceptor: After validatingStack: /pages/viewpage.action (ViewPageAction.execute())" and there is 0ms difference between the two:

DEBUG [TP-Processor9] [atlassian.util.profiling.UtilTimerStack] log [437ms] - /display/TEST/MyTestPage
(...)
  [312ms] - XW Interceptor: Before defaultStack: /pages/viewpage.action (ViewPageAction.execute())
    (...)
    [281ms] - XW Interceptor: After defaultStack: /pages/viewpage.action (ViewPageAction.execute())
      [281ms] - XW Interceptor: After validatingStack: /pages/viewpage.action (ViewPageAction.execute())
        [281ms] - XW View: doExecute(/pages/viewpage.vm)
            (...)
  [0ms] - UserAccessor.getUser()
  [0ms] - SpaceManager.getSpace()
  [109ms] - SiteMesh: applyDecorator: main (/decorators/main.vmd)

When we add a single User Profile Macro from communardo there is a large time difference between above two actions (593ms), suggesting that other actions take more time. However profiling shows only [0ms] actions in between:

DEBUG [TP-Processor9] [atlassian.util.profiling.UtilTimerStack] log [1016ms] - /display/TEST/MyTestPage
(...)
  [875ms] - XW Interceptor: Before defaultStack: /pages/viewpage.action (ViewPageAction.execute())
    (...)
    [859ms] - XW Interceptor: After defaultStack: /pages/viewpage.action (ViewPageAction.execute())
      [859ms] - XW Interceptor: After validatingStack: /pages/viewpage.action (ViewPageAction.execute())
        [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserAccessor.getUserProfilePicture()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserStatusManager.getUserStatus()
        [0ms] - PermissionManager.isConfluenceAdministrator()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserAccessor.getUserProfilePicture()
        [0ms] - UserAccessor.getUser()
        [0ms] - PermissionManager.isConfluenceAdministrator()
        [0ms] - PermissionManager.isConfluenceAdministrator()
        [0ms] - WikiStyleRenderer.convertWikiToXHtml()
        [0ms] - UserAccessor.getUser()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - ContentPropertyManager.getStringProperty()
        [0ms] - WikiStyleRenderer.convertWikiToXHtml()
        [0ms] - UserAccessor.getUser()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - ContentPropertyManager.getStringProperty()
        [0ms] - WikiStyleRenderer.convertWikiToXHtml()
        [0ms] - UserAccessor.getUser()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - ContentPropertyManager.getStringProperty()
        [0ms] - WikiStyleRenderer.convertWikiToXHtml()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserAccessor.getUserProfilePicture()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserAccessor.getUserProfilePicture()
        [0ms] - UserAccessor.getUser()
        [0ms] - WikiStyleRenderer.convertWikiToXHtml()
          [0ms] - UserAccessor.getUser()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - SpaceManager.getPersonalSpace()
        [0ms] - WikiStyleRenderer.convertWikiToXHtml()
        [0ms] - Rendering velocity template: vm/macros/enhanced-user-profile-macro.vm
          [0ms] - Parse: vm/velocity-macros.vm
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - UserAccessor.getUserProfilePicture()
          [0ms] - UserAccessor.getUser()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - UserAccessor.getUser()
          [0ms] - PermissionManager.hasPermission()
        [266ms] - XW View: doExecute(/pages/viewpage.vm)
            (...)
  [0ms] - UserAccessor.getUser()
  [0ms] - SpaceManager.getSpace()
  [125ms] - SiteMesh: applyDecorator: main (/decorators/main.vmd)

The same page but with communardo's plugin disabled (therefore displaying system default user profile macro) has some actions in between but again time difference is 15ms:

DEBUG [TP-Processor7] [atlassian.util.profiling.UtilTimerStack] log [515ms] - /display/TEST/MyTestPage
  (...)
  [359ms] - XW Interceptor: Before defaultStack: /pages/viewpage.action (ViewPageAction.execute())
    (...)
    [359ms] - XW Interceptor: After defaultStack: /pages/viewpage.action (ViewPageAction.execute())
      [359ms] - XW Interceptor: After validatingStack: /pages/viewpage.action (ViewPageAction.execute())
        [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getUser()
        [0ms] - UserStatusManager.getUserStatus()
        [0ms] - PermissionManager.isConfluenceAdministrator()
        [0ms] - Rendering velocity template: /includes/profile-macro.vm
          [0ms] - UserAccessor.getUserProfilePicture()
            [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - UserAccessor.getUser()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - ContentPropertyManager.getStringProperty()
          [0ms] - WikiStyleRenderer.convertWikiToXHtml()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - ContentPropertyManager.getStringProperty()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - ContentPropertyManager.getStringProperty()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - ContentPropertyManager.getStringProperty()
          [0ms] - WikiStyleRenderer.convertWikiToXHtml()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - ContentPropertyManager.getStringProperty()
          [0ms] - WikiStyleRenderer.convertWikiToXHtml()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - ContentPropertyManager.getStringProperty()
          [0ms] - WikiStyleRenderer.convertWikiToXHtml()
        [344ms] - XW View: doExecute(/pages/viewpage.vm)
          (...)
  [0ms] - UserAccessor.getUser()
  [0ms] - SpaceManager.getSpace()
  [156ms] - SiteMesh: applyDecorator: main (/decorators/main.vmd)

 

What might cause such slow performance of the Communardo's User Profile macro? Is there any way to make it faster? We really want to buy this plugin, but so far the slow performance is a blocker for us

Communardo Support_9414gm

Hello Blazej Olszyca,

it seems that the add-on needs quite a lot of loading time on your server. The time traces do not contain the rendering time of your browser.

We'd like to analyse this problem you face. Could you please open a support ticket in our Service Desk so we can dive into this? We do not want to analyse this on the publicly visible Atlassian Answers site as the information we require are not supposed to be visible to others.

Of course we will document the solution at this blog entry afterwards.

 

Kind regards,

 

Communardo Support