[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

Thiago Masutti made changes - 11/Jun/2019 8:52 PM

Labels

Original: affects-server logging&auditing

New: affects-server data-center logging&auditing pse-request

Thiago Masutti made changes - 11/Jun/2019 8:52 PM

Affects Version/s		New: 6.13.4 [ 85797 ]
Affects Version/s		New: 6.8.2 [ 78891 ]

Katherine Yabut made changes - 13/Nov/2018 4:45 AM

Workflow

Original: JAC Bug Workflow v3 [ 2884963 ]

New: CONFSERVER Bug Workflow v4 [ 2994778 ]

Owen made changes - 11/Oct/2018 8:49 AM

Workflow	Original: JAC Bug Workflow v2 [ 2789620 ]	New: JAC Bug Workflow v3 [ 2884963 ]
Status	Original: Resolved [ 5 ]	New: Closed [ 6 ]

Adam Barnes (Inactive) made changes - 20/Sep/2018 1:11 PM

Resolution		New: Timed out [ 10 ]
Status	Original: Gathering Impact [ 12072 ]	New: Resolved [ 5 ]

Owen made changes - 29/Aug/2018 11:16 PM

Workflow

Original: JAC Bug Workflow [ 2720523 ]

New: JAC Bug Workflow v2 [ 2789620 ]

Owen made changes - 17/Aug/2018 6:23 AM

Symptom Severity

Original: Minor [ 14432 ]

New: Severity 3 - Minor [ 15832 ]

Owen made changes - 02/Jul/2018 6:56 AM

Workflow	Original: Confluence Workflow - Public Facing - Restricted v5 - TEMP [ 2384022 ]	New: JAC Bug Workflow [ 2720523 ]
Status	Original: Open [ 1 ]	New: Gathering Impact [ 12072 ]

Katherine Yabut made changes - 22/Jun/2017 6:48 AM

Workflow

Original: Confluence Workflow - Public Facing - Restricted v5 [ 2278223 ]

New: Confluence Workflow - Public Facing - Restricted v5 - TEMP [ 2384022 ]

Katherine Yabut made changes - 31/May/2017 5:34 AM

Workflow

Original: Confluence Workflow - Public Facing - Restricted v5.1 - TEMP [ 2219911 ]

New: Confluence Workflow - Public Facing - Restricted v5 [ 2278223 ]

Assignee:: Unassigned

Reporter:: Eduardo Mallmann (Inactive)

Affected customers:: 3 This affects my team

Watchers:: 6 Start watching this issue

Created:: 20/Jun/2014 4:10 PM

Updated:: 11/Jun/2019 8:54 PM

Resolved:: 20/Sep/2018 1:11 PM

Details

Description

Attachments

Forms

Activity

People

Dates