[CONFSERVER-34023] Missing information on Profiling Log

Type: Bug
Resolution: Timed out
Priority: Low
Fix Version/s: None
Affects Version/s: 5.4, 5.5.2, 6.8.2, 6.13.4
Component/s: Server - Administration
Labels:

Support reference count:
3
Symptom Severity:
Severity 3 - Minor
Bug Fix Policy:
View Atlassian Server bug fix policy

The problem:
There is missing information on the Profiling Log.

Details:
Analysing a Profiling Log, it was noticed that there’s missing information on it.

In a specific case (as follow the logs below), a page took approximately 30 seconds to load. Looking at the profiling log, it's not possible to know what is taking that long, since the log file does not show every request made.

2014-06-19 13:54:50,849 DEBUG [http-8787-35] [atlassian.util.profiling.UtilTimerStack] log [29160ms] - /display/SpaceName/PageName
  [0ms] - UserAccessor.getExistingUserByKey()
  [0ms] - UserAccessor.getExistingUserByKey()
  [0ms] - UserAccessor.getUserByName()
  [0ms] - UserAccessor.getExistingUserByKey()
  [0ms] - UserAccessor.getExistingUserByKey()
  [0ms] - UserAccessor.getExistingUserByKey()
  [0ms] - UserAccessor.getExistingUserByKey()
  [0ms] - UserAccessor.getUserByName()
  [0ms] - UserAccessor.getExistingUserByKey()
  [28920ms] - XW Interceptor: Before defaultStack: /pages/viewpage.action (ViewPageAction.execute())
    [0ms] - UserAccessor.exists()
    [0ms] - UserAccessor.getPropertySet()
    [0ms] - SpaceAwareInterceptor.intercept()
    [3ms] - PageAwareInterceptor.intercept()
      [2ms] - PageManager.getPage()
      [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getGroup()
        [0ms] - UserAccessor.hasMembership()
      [0ms] - PermissionManager.hasPermission()
    [0ms] - CommentAwareInterceptor.intercept()
    [0ms] - UserAwareInterceptor.intercept()
    [0ms] - BootstrapAwareInterceptor.intercept()
    [0ms] - PermissionManager.hasPermission()
    [28908ms] - XW Interceptor: After defaultStack: /pages/viewpage.action (ViewPageAction.execute())
      [28908ms] - XW Interceptor: After validatingStack: /pages/viewpage.action (ViewPageAction.execute())
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [1ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [1ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [1ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - PageManager.getPage()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - UserAccessor.getUserByKey()
        [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
        [227ms] - XW View: doExecute(/pages/viewpage.vm)
          [0ms] - XW View: getTemplate(/pages/viewpage.vm)
          [227ms] - ApplyDecoratorDirective.render()
            [0ms] - SpaceManager.getSpace()
            [224ms] - Rendering velocity template: /decorators/root.vmd
              [224ms] - ApplyDecoratorDirective.render()
                [224ms] - Rendering velocity template: doctheme/decorators/page.vmd
                  [2ms] - WikiStyleRenderer.convertWikiToXHtml()
                    [2ms] - Rendering macro: {pagetree}
                      [1ms] - SpaceManager.getSpace()
                      [1ms] - Rendering velocity template: vm/tree.vm
                  [1ms] - WikiStyleRenderer.convertWikiToXHtml()
                    [1ms] - Rendering macro: {html}
                  [0ms] - WikiStyleRenderer.convertWikiToXHtml()
                    [0ms] - Rendering macro: {html}
                  [0ms] - WikiStyleRenderer.convertWikiToXHtml()
                  [0ms] - WikiStyleRenderer.convertWikiToXHtml()
                  [109ms] - Parse: /decorators/includes/content-navigation.vm
                    [0ms] - PermissionManager.hasPermission()
                    [2ms] - NotificationManager.getNotificationByUserAndPage()
                    [1ms] - NotificationManager.getNotificationByUserAndSpace()
                    [2ms] - NotificationManager.getNotificationByUserAndSpaceAndType()
                    [0ms] - PermissionManager.hasPermission()
                    [2ms] - NotificationManager.getNotificationByUserAndPage()
                    [0ms] - NotificationManager.getNotificationByUserAndSpace()
                    [1ms] - NotificationManager.getNotificationByUserAndSpaceAndType()
                    [0ms] - PermissionManager.hasPermission()
                    [1ms] - NotificationManager.getNotificationByUserAndPage()
                    [1ms] - NotificationManager.getNotificationByUserAndSpace()
                    [1ms] - NotificationManager.getNotificationByUserAndSpaceAndType()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [8ms] - PageTemplateManager.getGlobalPageTemplates()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - SpacePermissionManager.hasPermission()
                      [0ms] - UserAccessor.getGroup()
                      [0ms] - UserAccessor.hasMembership()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.isConfluenceAdministrator()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasCreatePermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                  [2ms] - Parse: /decorators/includes/page-content-includes.vm
                    [0ms] - Parse: /template/includes/actionerrors.vm
                    [1ms] - Parse: /decorators/includes/link-to-this-page.vm
                    [0ms] - Parse: /template/includes/page-move-templates.vm
                      [0ms] - PermissionManager.hasPermission()
                    [1ms] - Parse: /template/includes/search-results-grid-templates.vm
                  [4ms] - Parse: /decorators/includes/page-metadata-with-icons.vm
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - PermissionManager.hasPermission()
                    [0ms] - UserAccessor.getConfluenceUserPreferences()
                    [0ms] - FormatSettingsManager.getDateFormat()
                    [0ms] - FormatSettingsManager.getDateTimeFormat()
                    [0ms] - FormatSettingsManager.getTimeFormat()
                    [0ms] - FormatSettingsManager.getDateFormat()
                    [0ms] - FormatSettingsManager.getDateTimeFormat()
                    [0ms] - FormatSettingsManager.getEditorBlogPostDate()
                    [0ms] - Rendering velocity template: /includes/skiplinked-section.vm
                  [2ms] - Parse: /labels/labels-editor.vm
                    [1ms] - Parse: /labels/labels-editor-content.vm
                      [1ms] - Parse: /labels/labels-list.vm
                        [1ms] - Parse: /labels/label.vm
                  [0ms] - UserAccessor.getPropertySet()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [37ms] - ApplyDecoratorDirective.render()
                    [0ms] - SpaceManager.getSpace()
                    [36ms] - Rendering velocity template: /decorators/root.vmd
                      [36ms] - ApplyDecoratorDirective.render()
                        [0ms] - SpaceManager.getSpace()
                        [36ms] - Rendering velocity template: /decorators/components/comments.vmd
                          [2ms] - NotificationManager.getNotificationByUserAndContent()
                          [0ms] - NotificationManager.getNotificationByUserAndSpaceAndType()
                          [32ms] - Rendering velocity template: templates/quick-comment.vm
                            [1ms] - PermissionManager.hasCreatePermission()
                            [0ms] - UserAccessor.getUserProfilePicture()
                              [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
                            [1ms] - Rendering soy template: com.atlassian.confluence.plugins.quickedit:quick-comment-initial:Confluence.Templates.Comments.displayTopLevelCommentEditorPlaceholder.soy
                            [0ms] - UserAccessor.getPropertySet()
                            [0ms] - UserAccessor.getPropertySet()
                          [0ms] - PermissionManager.hasCreatePermission()
                          [0ms] - UserAccessor.getPropertySet()
                  [8ms] - Parse: /pages/page-breadcrumbs.vm
                    [8ms] - Parse: /breadcrumbs.vm
                  [0ms] - PermissionManager.hasPermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasPermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasPermission()
                  [1ms] - PageTemplateManager.getGlobalPageTemplates()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasPermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasPermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasPermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasPermission()
                  [0ms] - PermissionManager.hasCreatePermission()
                  [0ms] - PermissionManager.hasCreatePermission()
  [225ms] - SiteMesh: applyDecorator: main (doctheme/decorators/main.vmd)
    [222ms] - Rendering velocity template: doctheme/decorators/main.vmd
      [195ms] - Parse: /decorators/includes/header.vm
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getPropertySet()
        [1ms] - UserAccessor.getUserByName()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getUserProfilePicture()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getUserPreferences()
        [0ms] - PermissionManager.isConfluenceAdministrator()
        [0ms] - PermissionManager.isConfluenceAdministrator()
        [0ms] - UserAccessor.getConfluenceUserPreferences()
        [1ms] - Rendering velocity template: com/atlassian/confluence/extra/calendar3/messages.vm
        [94ms] - Rendering velocity template: templates/editor-header.vm
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - UserAccessor.getUserByName()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - UserAccessor.getPropertySet()
          [1ms] - UserAccessor.getUser()
          [0ms] - UserAccessor.getUserByKey()
        [0ms] - Rendering velocity template: templates/date-header.vm
          [0ms] - FormatSettingsManager.getDateFormat()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getUserByName()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getPropertySet()
        [0ms] - UserAccessor.getPropertySet()
        [1ms] - UserAccessor.getUserByName()
        [0ms] - PermissionManager.hasPermission()
        [0ms] - UserAccessor.getPropertySet()
      [0ms] - Parse: /decorators/includes/main-content-includes.vm
        [0ms] - Parse: /template/includes/global-settings.vm
      [0ms] - MessageManager.getMessages()
      [21ms] - Parse: /decorators/includes/common-header.vm
        [5ms] - Parse: /decorators/includes/aui-header-primary.vm
          [0ms] - PermissionManager.hasPermission()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - SpaceManager.getSpaces()
          [0ms] - UserAccessor.isSuperUser()
          [0ms] - SpaceManager.getSpaces()
          [1ms] - UserAccessor.isSuperUser()
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - PermissionManager.isConfluenceAdministrator()
          [0ms] - UserAccessor.getPropertySet()
        [11ms] - Parse: /decorators/includes/aui-header-secondary.vm
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - PermissionManager.isConfluenceAdministrator()
          [0ms] - PermissionManager.isConfluenceAdministrator()
          [0ms] - PermissionManager.isConfluenceAdministrator()
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - PermissionManager.isConfluenceAdministrator()
          [0ms] - PermissionManager.isConfluenceAdministrator()
          [0ms] - PermissionManager.hasPermission()
          [0ms] - UserAccessor.getUserProfilePicture()
          [0ms] - PermissionManager.hasCreatePermission()
          [1ms] - SpaceManager.getPersonalSpace()
          [1ms] - SpaceManager.getPersonalSpace()
          [0ms] - PersonalInformationManager.getOrCreatePersonalInformation()
          [0ms] - PermissionManager.hasCreatePermission()
          [0ms] - PermissionManager.hasCreatePermission()
        [4ms] - Rendering soy template: com.atlassian.plugins.atlassian-nav-links-plugin:rotp-menu:navlinks.templates.appswitcher.switcher.soy
          [0ms] - UserAccessor.getPropertySet()
          [0ms] - UserAccessor.getUserByName()
          [0ms] - PermissionManager.hasPermission()
        [1ms] - Rendering soy template: com.atlassian.auiplugin:aui-experimental-soy-templates:aui.page.header.soy
      [0ms] - Rendering velocity template: /decorators/includes/footer.vm
        [0ms] - Parse: /decorators/includes/footer-content.vm

When summing up the milliseconds the page took to load, the result will not be even close to the total it shows at the beginning (29160ms).

This specific page was taking that long to load due to a bug on the Jira Issue Macro, however the profiling log does not mention this macro and not even a request to JIRA.

Request:
We know that the profiling is not showing the Jira Issue Macro, so it might not be showing other macros either.

Would be great to have this kind of information on the log, so it would be easier to know what is happening.

Steps to Reproduce:

Configure your Confluence to use Application Links with your JIRA.
Enable the Performance Profiling under Confluence Admin > Logging and Profiling > Performance Profiling.
Create a page in Confluence and add the Jira Issues macro.
Create a filter to get some issues from your JIRA showing in the macro.
Save the page and access it afterwards.
Check the profiling logs.

Note that there's nothing related to the JIRA Issues macro in the profiling logs.

Form Name

Details

Description

Attachments

Forms

Activity

People

Dates