Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-29310

Filter gadgets take several minutes to load after a field configuration context change

XMLWordPrintable

    • 5.01
    • 37
    • Severity 2 - Major
    • 45
    • Hide
      Atlassian Update – 21 December 2018

      Dear Jira users,

      We’re glad to announce that this issue will be addressed in our upcoming 8.0 release.

      You can find more details about our 8.0 beta release here — https://community.developer.atlassian.com/t/beta-for-jira-8-0-is-up-for-grabs/25588

      Looking forward to your feedback!

      Kind regards,
      Syed Masood
      Product Manager, Jira Server and Data Center

      Show
      Atlassian Update – 21 December 2018 Dear Jira users, We’re glad to announce that this issue will be addressed in our upcoming 8.0 release. You can find more details about our 8.0 beta release here — https://community.developer.atlassian.com/t/beta-for-jira-8-0-is-up-for-grabs/25588 Looking forward to your feedback! Kind regards, Syed Masood Product Manager, Jira Server and Data Center

      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

      1. Perform a field configuration context change on a large instance.
      2. 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

        1. stacktrace-log
          150 kB
        2. stacktrace-open-issues-menue.txt
          153 kB
        3. stacktrace-issue-navigator.txt
          135 kB
        4. congestion on cache.jpg
          congestion on cache.jpg
          1.32 MB

              izinoviev Ilya Zinoviev (Inactive)
              jalbion Janet Albion (Inactive)
              Votes:
              32 Vote for this issue
              Watchers:
              54 Start watching this issue

                Created:
                Updated:
                Resolved: