-
Bug
-
Resolution: Fixed
-
Highest
-
5.1.2, 5.1.8, 6.3.4, 7.1.4, 7.0.11, 7.2.2, 7.2.8, 7.6.7
-
5.01
-
37
-
Severity 2 - Major
-
45
-
-
Summary
As of JIRA 5.1.2, each time the user changes a field configuration context (e.g. add a project to a context) it can take minutes to display the dashboard with some filter gadgets on it, or load other requests that access the cache. The bar on the gadget just keeps spinning. The field that has been changed before switching to the dashboard was not related to any of the fields known to the projects defined in the gadget filters.
This behaviour continues until the original thread finishes completing the cache population, then the other threads can complete as the cache is then loaded into memory.
Environment
Large amount of fieldlayouts items:
SQL> select count(1) from fieldlayout; 576 SQL> select count(1) from fieldlayoutitem; 1355666 SQL> select count(1) from fieldlayoutscheme; 492
Steps to Reproduce
- Perform a field configuration context change on a large instance.
- Access the dashboard with filter gadgets on it.
Expected Results
The dashboard loads as normal.
Actual Results
The dashboard loads much more slowly than normal. Generating a Thread Dump as per those docs will show stack traces such as the related thread dump below:
"http-21443-1" daemon prio=10 tid=0x0000000049ae6000 nid=0x1ea2 runnable [0x00000000435d5000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188) - locked <0x00000007488809a0> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2494) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2949) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2938) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3481) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2109) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648) - locked <0x0000000748880c98> (a java.lang.Object) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2077) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2228) - locked <0x0000000748880c98> (a java.lang.Object) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) at org.ofbiz.core.entity.jdbc.SQLProcessor.executeQuery(SQLProcessor.java:597) at org.ofbiz.core.entity.GenericDAO.selectListIteratorByCondition(GenericDAO.java:1059) at org.ofbiz.core.entity.GenericDAO.selectByAnd(GenericDAO.java:607) at org.ofbiz.core.entity.GenericHelperDAO.findByAnd(GenericHelperDAO.java:131) at org.ofbiz.core.entity.GenericDelegator.findByAnd(GenericDelegator.java:788) at org.ofbiz.core.entity.GenericDelegator.findByAnd(GenericDelegator.java:773) at org.ofbiz.core.entity.GenericDelegator.getRelated(GenericDelegator.java:1209) at org.ofbiz.core.entity.GenericDelegator.getRelated(GenericDelegator.java:1155) at org.ofbiz.core.entity.GenericValue.getRelated(GenericValue.java:137) at com.atlassian.jira.issue.fields.layout.field.AbstractFieldLayoutManager.loadFieldLayout(AbstractFieldLayoutManager.java:392) at com.atlassian.jira.issue.fields.layout.field.AbstractFieldLayoutManager.access$000(AbstractFieldLayoutManager.java:42) at com.atlassian.jira.issue.fields.layout.field.AbstractFieldLayoutManager$1.load(AbstractFieldLayoutManager.java:56) at com.atlassian.jira.issue.fields.layout.field.AbstractFieldLayoutManager$1.load(AbstractFieldLayoutManager.java:52) at com.google.common.cache.CustomConcurrentHashMap$ComputingValueReference.compute(CustomConcurrentHashMap.java:3426) at com.google.common.cache.CustomConcurrentHashMap$Segment.compute(CustomConcurrentHashMap.java:2322) - locked <0x00000007d452e630> (a com.google.common.cache.CustomConcurrentHashMap$StrongEntry) at com.google.common.cache.CustomConcurrentHashMap$Segment.getOrCompute(CustomConcurrentHashMap.java:2291) at com.google.common.cache.CustomConcurrentHashMap.getOrCompute(CustomConcurrentHashMap.java:3802) at com.google.common.cache.ComputingCache.get(ComputingCache.java:46) at com.google.common.cache.AbstractCache.getUnchecked(AbstractCache.java:49) at com.atlassian.jira.issue.fields.layout.field.AbstractFieldLayoutManager.getRelevantFieldLayout(AbstractFieldLayoutManager.java:338) at com.atlassian.jira.issue.fields.layout.field.DefaultFieldLayoutManager.getFieldLayout(DefaultFieldLayoutManager.java:633) at com.atlassian.jira.issue.fields.layout.field.DefaultFieldLayoutManager.getUniqueFieldLayouts(DefaultFieldLayoutManager.java:491) at com.atlassian.jira.issue.fields.DefaultFieldManager.getUniqueSchemes(DefaultFieldManager.java:532) at com.atlassian.jira.issue.fields.DefaultFieldManager.isFieldHidden(DefaultFieldManager.java:562) at com.atlassian.jira.jql.permission.FieldClausePermissionChecker.hasPermissionToUseClause(FieldClausePermissionChecker.java:32) at com.atlassian.jira.jql.permission.DefaultClausePermissionHandler.hasPermissionToUseClause(DefaultClausePermissionHandler.java:36) at com.atlassian.jira.issue.search.managers.DefaultSearchHandlerManager.getClauseHandler(DefaultSearchHandlerManager.java:136) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.visit(ClauseSanitisingVisitor.java:66) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.visit(ClauseSanitisingVisitor.java:33) at com.atlassian.query.clause.TerminalClauseImpl.accept(TerminalClauseImpl.java:137) at com.atlassian.jira.bc.issue.search.DefaultSearchService.sanitiseSearchQuery(DefaultSearchService.java:300) at com.atlassian.jira.issue.search.DefaultSearchRequestManager.setSanitisedQuery(DefaultSearchRequestManager.java:261) at com.atlassian.jira.issue.search.DefaultSearchRequestManager.getSearchRequestById(DefaultSearchRequestManager.java:132) at com.atlassian.jira.bc.filter.DefaultSearchRequestService.getFilter(DefaultSearchRequestService.java:162) at com.atlassian.jira.charts.util.ChartUtilsImpl.retrieveOrMakeSearchRequest(ChartUtilsImpl.java:50) ....
Verification
Analysis of thread dumps can indicate this is a problem, for example searching for the amount of threads in that filter method, specifically:
grep -c AbstractFieldLayoutManager.getRelevantFieldLayout thread_dump* thread_dump_1.txt:0 thread_dump_2.txt:11 thread_dump_3.txt:25 thread_dump_4.txt:28 thread_dump_5.txt:36 thread_dump_6.txt:0 thread_dump_7.txt:0
Here we can see a large amount of threads are within that method over a period of time, which indicates the instance is likely affected by this bug.
Additionally there will be a large amount of threads waiting on futures, which means they're waiting on the cache to be completed. They appear as below in a thread dump:
"http-bio-10.35.136.254-8443-exec-949" #30351 daemon prio=5 tid=0x00007f3b88024000 nid=0x9ebf waiting on condition [0x00007f38ca572000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000775ae5170> (a com.google.common.util.concurrent.AbstractFuture$Sync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304) at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285) at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:137) at com.google.common.cache.LocalCache$LoadingValueReference.waitForValue(LocalCache.java:3557) at com.google.common.cache.LocalCache$Segment.waitForLoadingValue(LocalCache.java:2302) at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2191) at com.google.common.cache.LocalCache.get(LocalCache.java:3937) at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4739) at com.atlassian.cache.memory.DelegatingCache.get(DelegatingCache.java:173) at com.atlassian.cache.memory.DelegatingCache.get(DelegatingCache.java:158) at com.atlassian.jira.issue.fields.layout.field.AbstractFieldLayoutManager.getRelevantFieldLayout(AbstractFieldLayoutManager.java:264) at com.atlassian.jira.issue.fields.layout.field.DefaultFieldLayoutManager.getFieldLayout(DefaultFieldLayoutManager.java:694) at com.atlassian.jira.issue.fields.layout.field.DefaultFieldLayoutManager.getUniqueFieldLayouts(DefaultFieldLayoutManager.java:578) at com.atlassian.jira.issue.fields.layout.field.DefaultFieldLayoutManager.getUniqueFieldLayouts(DefaultFieldLayoutManager.java:554) at com.atlassian.jira.issue.fields.DefaultFieldManager.findVisibleFieldLayouts(DefaultFieldManager.java:503) at com.atlassian.jira.issue.fields.DefaultFieldManager.getUniqueSchemes(DefaultFieldManager.java:419) at com.atlassian.jira.issue.fields.DefaultFieldManager.access$000(DefaultFieldManager.java:46) at com.atlassian.jira.issue.fields.DefaultFieldManager$1.load(DefaultFieldManager.java:124) at com.atlassian.jira.issue.fields.DefaultFieldManager$1.load(DefaultFieldManager.java:120) at com.atlassian.jira.cache.request.RequestCacheImpl.get(RequestCacheImpl.java:42) at com.atlassian.jira.issue.fields.DefaultFieldManager.getVisibleFieldLayouts(DefaultFieldManager.java:447) at com.atlassian.jira.issue.fields.DefaultFieldManager.isFieldHidden(DefaultFieldManager.java:441) at com.atlassian.jira.jql.permission.FieldClausePermissionChecker.hasPermissionToUseClause(FieldClausePermissionChecker.java:32) at com.atlassian.jira.jql.permission.DefaultClausePermissionHandler.hasPermissionToUseClause(DefaultClausePermissionHandler.java:41) at com.atlassian.jira.issue.search.managers.DefaultSearchHandlerManager.getClauseHandler(DefaultSearchHandlerManager.java:148) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.visit(ClauseSanitisingVisitor.java:60) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.visit(ClauseSanitisingVisitor.java:33) at com.atlassian.query.clause.TerminalClauseImpl.accept(TerminalClauseImpl.java:143) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.sanitiseChildren(ClauseSanitisingVisitor.java:131) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.visit(ClauseSanitisingVisitor.java:46) at com.atlassian.jira.jql.permission.ClauseSanitisingVisitor.visit(ClauseSanitisingVisitor.java:33) at com.atlassian.query.clause.AndClause.accept(AndClause.java:28) at com.atlassian.jira.bc.issue.search.DefaultSearchService.process(DefaultSearchService.java:301) at com.atlassian.jira.bc.issue.search.DefaultSearchService.sanitiseSearchQuery(DefaultSearchService.java:292) at com.atlassian.jira.issue.search.DefaultSearchRequestManager.setSanitisedQuery(DefaultSearchRequestManager.java:282) at com.atlassian.jira.issue.search.DefaultSearchRequestManager.getSearchRequestById(DefaultSearchRequestManager.java:146) at com.atlassian.jira.bc.filter.DefaultSearchRequestService.getFilter(DefaultSearchRequestService.java:128) at sun.reflect.GeneratedMethodAccessor485.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26) at com.sun.proxy.$Proxy112.getFilter(Unknown Source) at sun.reflect.GeneratedMethodAccessor485.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean$DynamicServiceInvocationHandler.invoke(HostComponentFactoryBean.java:136) at com.sun.proxy.$Proxy112.getFilter(Unknown Source) at com.atlassian.greenhopper.service.rapid.SavedFilterServiceImpl.getSavedFilter(SavedFilterServiceImpl.java:199) at com.atlassian.greenhopper.service.rapid.view.RapidViewPermissionServiceImpl.canSeeRapidView(RapidViewPermissionServiceImpl.java:35) at com.atlassian.greenhopper.service.rapid.view.RapidViewServiceImpl.getRapidView(RapidViewServiceImpl.java:237) at com.atlassian.greenhopper.web.rapid.work.WorkResource$1.call(WorkResource.java:66) at com.atlassian.greenhopper.web.rapid.work.WorkResource$1.call(WorkResource.java:59) at com.atlassian.greenhopper.web.util.RestCall.response(RestCall.java:42) at com.atlassian.greenhopper.web.AbstractResource.createResponse(AbstractResource.java:111) at com.atlassian.greenhopper.web.AbstractResource.response(AbstractResource.java:91) at com.atlassian.greenhopper.web.rapid.work.WorkResource.getPoolData(WorkResource.java:58) ...
There is an example of how this looks in TDA attached to this issue.
Workaround
Please see JRASERVER-66013
- is caused by
-
JRASERVER-66013 JIRA inefficiently populates fieldLayoutCache due to slow loading of FieldLayoutItems
- Closed
-
JRASERVER-68168 Make FieldLayoutCache population more efficient in Jira
- Gathering Interest
- is related to
-
JRASERVER-29259 JIRA View Custom Fields Page Performance Issues
- Closed
-
JRASERVER-61166 Performance of JIRA Datacenter degrades significantly after customfields configuration task
- Gathering Impact
-
JRASERVER-61704 Slow loading of Project - Fields screen
- Gathering Impact
- relates to
-
JRASERVER-61383 JIRA Software can become unresponsive on upgrade or install when there are many custom fields due to restoring and locking all fields
- Closed
-
GHS-8317 Loading...
-
RAID-106 Loading...
-
RUM-635 Loading...
-
SIN-357 Loading...
- is blocked by
-
PSR-38 Loading...
- Mentioned in
- 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...
-
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...
- was cloned as
-
RAID-35 Loading...