Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Fixed
Priority: High
Fix Version/s: 7.17.0
Affects Version/s: 6.9.1, 6.13.2, 6.13.17, 7.4.4
Component/s: Macros - Other Macros
Labels:

Support reference count:
44
Symptom Severity:
Severity 2 - Major
UIS:
18
Bug Fix Policy:
View Atlassian Server bug fix policy

Description

Resolution requires the faster permissions service

To resolve this issue you will need to enable the faster permissions service in your site.

Issue Summary

When loading a page with the Page Index Macro, the page takes a long time to render.
If a timeout is configured (i.e. from a proxy), then the page is not loaded because of it.

Depending on how many times the macro is loaded at the same time, it may overload the Confluence server and eventually make it unusable.

Steps to Reproduce

Have a fresh install of Confluence.
Login to Confluence as an admin (part of the confluence-administrators group).
Create a sample Space and add thousands of pages to it.
- 1k pages is enough as a proof of concept.
- If you want to add more complexity to the issue, create 4.5k pages.
Create a page in the same space and add the Page Index Macro.
- When the page is loaded after saving it, the macro will render fast – this occurs because the admin bypass the page restrictions validation.
Login to Confluence as a regular user (not part of the confluence-administrators group).
Access the page with the Page Index Macro.

Expected Results

A page with the Page Index Macro will load within an acceptable time and the user won't experience a delay on rendering the macro.

Actual Results

The page takes a long time to load, but will eventually.
In a simple computer, this is the time the macro takes to render depending on the number of pages within the Space:

Number of pages	Time (s)
100	0
250	0
500	8
1,000	32
2,500	252
4,998	961

The results may differ depending on the HW used to run the tests, but it is clear the time to render the macro doesn't scale linearly with the number of pages.

Notes

The situation may worsen because the macro is rendered synchronously. That means Confluence must fetch the macro content before retrieving any content to the user's client (browser).
The user might think the request was not processed and may try to refresh the page or try to access it in other browser windows, triggering new threads that will add more overhead to the Confluence backend.

Depending on several parameters (number of users trying to access the same page, an user refreshing the page multiple times, complexity of the Space), this macro may create a situation on which the HW resources (CPU, memory) will be highly consumed and eventually bring the instance down (or make it unusable to the users).

How to identify if affected by this issue

Taking thread dumps during periods of high load, or before restarting Confluence on the event of an incident, shows one or more HTTP threads stuck with a similar stack trace as below.

"http-nio-26132-exec-8" #63 daemon prio=5 os_prio=31 tid=0x00007fc57bf64000 nid=0xb503 runnable [0x0000700014981000]
   java.lang.Thread.State: RUNNABLE
(...)
	at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1441)
	at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1410)
	at com.atlassian.confluence.security.persistence.dao.hibernate.HibernateContentPermissionSetDao.lambda$getInheritedContentPermissionSets$2(HibernateContentPermissionSetDao.java:109)
	at com.atlassian.confluence.security.persistence.dao.hibernate.HibernateContentPermissionSetDao$$Lambda$1101/1350530201.doInHibernate(Unknown Source)
	at org.springframework.orm.hibernate5.HibernateTemplate.doExecute(HibernateTemplate.java:361)
	at org.springframework.orm.hibernate5.HibernateTemplate.execute(HibernateTemplate.java:315)
	at com.atlassian.confluence.security.persistence.dao.hibernate.HibernateContentPermissionSetDao.getInheritedContentPermissionSets(HibernateContentPermissionSetDao.java:80)
	at com.atlassian.confluence.core.DefaultInheritedContentPermissionManager.getInheritedContentPermissionSets(DefaultInheritedContentPermissionManager.java:44)
	at com.atlassian.confluence.core.DefaultInheritedContentPermissionManager.getInheritedContentPermissionSetsIncludeEdit(DefaultInheritedContentPermissionManager.java:38)
	at com.atlassian.confluence.core.CachingInheritedContentPermissionManager.queryAndCache(CachingInheritedContentPermissionManager.java:71)
	at com.atlassian.confluence.core.CachingInheritedContentPermissionManager.getInheritedContentPermissionSets(CachingInheritedContentPermissionManager.java:62)
	at com.atlassian.confluence.core.CachingInheritedContentPermissionManager.getInheritedContentPermissionSetsIncludeEdit(CachingInheritedContentPermissionManager.java:45)
	at com.atlassian.confluence.core.DefaultContentPermissionManager.getInheritedContentPermissionSets(DefaultContentPermissionManager.java:155)
	at com.atlassian.confluence.core.DefaultContentPermissionManager.hasInheritedContentLevelViewPermissions(DefaultContentPermissionManager.java:256)
	at com.atlassian.confluence.core.DefaultContentPermissionManager.hasContentLevelPermission(DefaultContentPermissionManager.java:191)
(...)
	at com.sun.proxy.$Proxy213.hasContentLevelPermission(Unknown Source)
	at com.atlassian.confluence.security.delegate.PagePermissionsDelegate.hasContentLevelViewPermission(PagePermissionsDelegate.java:123)
	at com.atlassian.confluence.security.delegate.PagePermissionsDelegate.canView(PagePermissionsDelegate.java:20)
	at com.atlassian.confluence.security.delegate.PagePermissionsDelegate.canView(PagePermissionsDelegate.java:13)
	at com.atlassian.confluence.security.delegate.TargetToLatestVersionDecorator.canView(TargetToLatestVersionDecorator.java:24)
	at com.atlassian.confluence.security.delegate.SharedAccessInterceptor$$Lambda$1490/328114757.test(Unknown Source)
	at com.atlassian.confluence.security.delegate.SharedAccessInterceptor.checkAccess(SharedAccessInterceptor.java:88)
	at com.atlassian.confluence.security.delegate.SharedAccessInterceptor.canView(SharedAccessInterceptor.java:26)
	at com.atlassian.confluence.security.Permission$1.checkAgainst(Permission.java:17)
	at com.atlassian.confluence.security.DefaultPermissionManager.hasPermissionNoExemptions(DefaultPermissionManager.java:100)
	at com.atlassian.confluence.security.DefaultPermissionManager.hasPermission(DefaultPermissionManager.java:48)
	at com.atlassian.confluence.security.DefaultPermissionManager.getPermittedEntities(DefaultPermissionManager.java:149)
	at sun.reflect.GeneratedMethodAccessor2077.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
(...)
	at com.sun.proxy.$Proxy214.getPermittedEntities(Unknown Source)
	at com.atlassian.confluence.plugins.macros.advanced.IndexMacro.fetchPages(IndexMacro.java:126)
	at com.atlassian.confluence.plugins.macros.advanced.IndexMacro.getHtml(IndexMacro.java:86)
	at com.atlassian.confluence.renderer.radeox.macros.AbstractHtmlGeneratingMacro.execute(AbstractHtmlGeneratingMacro.java:46)
	at com.atlassian.renderer.macro.RadeoxCompatibilityMacro.execute(RadeoxCompatibilityMacro.java:149)
	at com.atlassian.confluence.renderer.v2.macros.RadeoxCompatibilityMacro.execute(RadeoxCompatibilityMacro.java:46)
	at com.atlassian.renderer.v2.macro.ResourceAwareMacroDecorator.execute(ResourceAwareMacroDecorator.java:51)
	at com.atlassian.confluence.macro.V2CompatibilityMacro.execute(V2CompatibilityMacro.java:36)
	at com.atlassian.confluence.macro.LazyLoadingMacroWrapper.execute(LazyLoadingMacroWrapper.java:24)
	at com.atlassian.confluence.content.render.xhtml.view.macro.ViewMacroMarshaller.executeMacro(ViewMacroMarshaller.java:255)
(...)
	at com.atlassian.confluence.content.render.xhtml.DefaultRenderer.render(DefaultRenderer.java:110)
	at com.atlassian.confluence.content.render.xhtml.DeviceTypeAwareRenderer.render(DeviceTypeAwareRenderer.java:43)
	at com.atlassian.confluence.pages.actions.ViewPageAction.execute(ViewPageAction.java:270)
	at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:168)
(...)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	- locked <0x0000000789650a78> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

Checking what Confluence does on the database, most of the time it is performing queries to validate if the current user has enough permissions to view the pages within the target Space.
Thousands of queries similar to the ones below may be found in the DB transaction log.

select contentent2_.CONTENTID as col_0_0_ from CONTENT page0_ left outer join CONFANCESTORS ancestors1_ on page0_.CONTENTID=ancestors1_.DESCENDENTID left outer join CONTENT contentent2_ on ancestors1_.ANCESTORID=contentent2_.CONTENTID where page0_.CONTENTTYPE='PAGE' and page0_.CONTENTID=$1

select contentper0_.ID as ID1_15_, contentper0_.CONT_PERM_TYPE as CONT_PER2_15_, contentper0_.CONTENT_ID as CONTENT_3_15_, contentper0_.CREATIONDATE as CREATION4_15_, contentper0_.LASTMODDATE as LASTMODD5_15_ from CONTENT_PERM_SET contentper0_ where contentper0_.CONT_PERM_TYPE=$1 and (contentper0_.CONTENT_ID in ($2))

With log profiling enabled you will notice most of the time is spent while doing permission management tasks.

2019-02-05 16:41:33,842 DEBUG [http-nio-26132-exec-8] [atlassian.util.profiling.UtilTimerStack] log [961657ms] - /c6132/display/SO5000/A+Page+Index+Macro
  [13ms] - UserAccessor.getUserByName()
(...)
      [960243ms] - XW Interceptor: After defaultStack: /pages/viewpage.action (ViewPageAction.execute())
        [960243ms] - XW Interceptor: After validatingStack: /pages/viewpage.action (ViewPageAction.execute())
          [0ms] - UserAccessor.getPropertySet()
          [958024ms] - DefaultRenderer.render
            [958024ms] - DefaultRenderer.renderWithResult
              [0ms] - UserAccessor.getPropertySet()
              [0ms] - UserAccessor.getPropertySet()
              [0ms] - UserAccessor.getPropertySet()
              [0ms] - UserAccessor.getPropertySet()
              [0ms] - SpaceManager.getSpace()
              [5ms] - PageManager.getPageCount()
              [237ms] - PageManager.getPagesWithPermissions()
              [957323ms] - PermissionManager.getPermittedEntities()
              [124ms] - Rendering velocity template: com/atlassian/confluence/plugins/macros/advanced/alphaindex.vm
              [1ms] - UserAccessor.getUserProfilePicture()
              [0ms] - UserAccessor.getPropertySet()
              [0ms] - UserAccessor.getUserProfilePicture()
              [0ms] - UserAccessor.getPropertySet()
(...)

Workaround

The Confluence administrator may add the below JVM argument to restrict the macro from running on large spaces:

-Dpage.index.macro.max.pages=500

Check this KB to know how to configure system properties.

Users will still be able to add the macro to pages, but when loading the page, the macro will render a message as the one below without running its background job:

Note that you must be in one of the versions that fix bug CONFSERVER-55450 to have this functionality working as expected.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List

space_index_message_img001.png
56 kB
06/Feb/2019 8:41 PM

Issue Links

is related to

CONFSERVER-40860 Page Index macro in large space is bringing down Confluence

Closed

CONFSERVER-55450 Page Index Macro max page threshold does not prevent macro from indexing beyond that limit

Closed

CONFSERVER-55412 Lower the default for page.index.macro.max.pages

Closed

mentioned in: Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...

(29 mentioned in)

Activity

People

Assignee:: George Lipatov

Reporter:: Thiago Masutti

Votes:: 15 Vote for this issue

Watchers:: 33 Start watching this issue

Dates

Created:: 06/Feb/2019 4:41 PM

Updated:: 16/Dec/2022 2:32 PM

Resolved:: 22/Mar/2022 12:35 AM