[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.

Adam Barnes (Inactive) added a comment - 20/Sep/2018 1:11 PM

Thank you for taking the time to raise, comment or vote on this Bug. We regret to inform you that due to a limited number of reports and based on our current backlog of higher impact issues that we are closing this issue as Timed Out.

If this issue is still impacting you on a recent version please feel free to comment with the affected version. Any further details you may be able to provide regarding reproduction or impact of this issue may help us better address this issue.

Thanks again.
Cheers,

Confluence Product Management

Adam Barnes (Inactive) added a comment - 20/Sep/2018 1:11 PM Thank you for taking the time to raise, comment or vote on this Bug. We regret to inform you that due to a limited number of reports and based on our current backlog of higher impact issues that we are closing this issue as Timed Out. If this issue is still impacting you on a recent version please feel free to comment with the affected version. Any further details you may be able to provide regarding reproduction or impact of this issue may help us better address this issue. Thanks again. Cheers, Confluence Product Management

Eduardo Mallmann (Inactive) added a comment - 23/Jun/2014 2:16 PM

Hello shaffenden,

I have just added the versions and the steps to reproduce.

Please, let me know if there's anything else you need.

Best regards,

Eduardo Mallmann
Atlassian Support

Eduardo Mallmann (Inactive) added a comment - 23/Jun/2014 2:16 PM Hello shaffenden , I have just added the versions and the steps to reproduce. Please, let me know if there's anything else you need. Best regards, Eduardo Mallmann Atlassian Support

Steve Haffenden (Inactive) added a comment - 22/Jun/2014 10:42 PM

Hi emallmann

Thanks for raising this ticket. Can you supply the following additional information:

Version of Confluence you are using
Steps to reproduce the issue

Regards
Steve Haffenden
Confluence Bugmaster
Atlassian

Steve Haffenden (Inactive) added a comment - 22/Jun/2014 10:42 PM Hi emallmann Thanks for raising this ticket. Can you supply the following additional information: Version of Confluence you are using Steps to reproduce the issue Regards Steve Haffenden Confluence Bugmaster Atlassian

Confluence Data Center

Details

Description

Attachments

Forms

Activity

Collapse comment: Adam Barnes (Inactive) added a comment - 20/Sep/2018 1:11 PM

Expand comment: Adam Barnes (Inactive) added a comment - 20/Sep/2018 1:11 PM

Collapse comment: Eduardo Mallmann (Inactive) added a comment - 23/Jun/2014 2:16 PM

Expand comment: Eduardo Mallmann (Inactive) added a comment - 23/Jun/2014 2:16 PM

Collapse comment: Steve Haffenden (Inactive) added a comment - 22/Jun/2014 10:42 PM

Expand comment: Steve Haffenden (Inactive) added a comment - 22/Jun/2014 10:42 PM

People

Dates