all JIRA threads is blocked waiting for cache getProjectContextIdsForQuery

Summary

JIRA is inaccessible and you get This site can’t be reached error. Almost all incoming http threads except one are blocked waiting for cache getProjectContextIdsForQuery to be populated.

Steps to Reproduce

1. Restart JIRA
2. Initiate large number of call loading data from getProjectContextIdsForQuery cache, eg: URL: /secure/BrowseProject.jspa
3. Check that JIRA is not accessible after some time.

Expected Results

JIRA is working fine

Actual Results

• Almost all threads are blocked waiting for cache getProjectContextIdsForQuery cache, example:

  http-bio-80-exec-88" #306 daemon prio=5 os_prio=0 tid=0x0000000032d35000 nid=0x1cb4 waiting on condition [0x000000025e419000]
     java.lang.Thread.State: WAITING (parking)
  	at sun.misc.Unsafe.park(Native Method)
  	- parking to wait for  <0x00000007b7c020f0> (a com.google.common.util.concurrent.AbstractFuture$Sync)
  ...
  	at com.atlassian.cache.memory.DelegatingCache$DelegatingLoadingCache.get(DelegatingCache.java:324)
  	at com.atlassian.cache.compat.delegate.DelegatingCache.get(DelegatingCache.java:37)
  	at com.atlassian.greenhopper.service.query.QueryToProjectMapper.getProjectContextIdsForQuery(QueryToProjectMapper.java:78)
  	at com.atlassian.greenhopper.service.query.QueryServiceImpl.getProjectsForRapidView(QueryServiceImpl.java:116)
  	at com.atlassian.greenhopper.service.query.QueryServiceImpl.getExplicitProjectsForRapidViewFilterQuery(QueryServiceImpl.java:103)
  	at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findProjectsByRapidView(ProjectRapidViewServiceImpl.java:57)
  	at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findRapidViewsByProject(ProjectRapidViewServiceImpl.java:40)
  	at com.atlassian.greenhopper.web.sidebar.ProjectBoardsHelper.getProjectBoards(ProjectBoardsHelper.java:53)
  	at com.atlassian.greenhopper.web.sidebar.BoardScopeFilterContextProviderImpl.getContext(BoardScopeFilterContextProviderImpl.java:37)
  	at com.atlassian.greenhopper.web.sidebar.AgileBoardScopeFilterContextProvider.getContext(AgileBoardScopeFilterContextProvider.java:27)
  	at com.atlassian.jira.projects.context.ProjectContextPopulator.populateWithProject(ProjectContextPopulator.java:77)
  	at com.atlassian.jira.projects.sidebar.content.ProjectContentRendererImpl.render(ProjectContentRendererImpl.java:35)
  	at com.atlassian.jira.projects.sidebar.ProjectSidebarRendererImpl.render(ProjectSidebarRendererImpl.java:78)
  	at com.atlassian.greenhopper.sidebar.ProjectSidebarRendererAdapterImpl.render(ProjectSidebarRendererAdapterImpl.java:21)
  	at com.atlassian.greenhopper.sidebar.ProjectSidebarRenderer.render(ProjectSidebarRenderer.java:45)
  	at com.atlassian.greenhopper.web.sidebar.BoardSidebarRenderer.getProjectSidebarHtml(BoardSidebarRenderer.java:157)
  	at com.atlassian.greenhopper.web.sidebar.BoardSidebarRenderer.getSidebarHtml(BoardSidebarRenderer.java:88)
  	at com.atlassian.greenhopper.web.rapid.RapidBoardAction.getSidebarHtml(RapidBoardAction.java:307)
  ...
  

• 1 thread is populating the cache getProjectContextIdsForQuery and same thread meanwhile busy doing other slow task, one of possible examples:

  "http-bio-80-exec-121" #345 daemon prio=5 os_prio=0 tid=0x00000000342d3800 nid=0x1130 runnable [0x0000000262a98000]
     java.lang.Thread.State: RUNNABLE
  	at java.net.SocketInputStream.socketRead0(Native Method)
  ...
          com.atlassian.greenhopper.service.query.FieldPossibleValuesAdapterImpl.possibleValuesForIssueInput(FieldPossibleValuesAdapterImpl.java:21)
  	at com.atlassian.greenhopper.service.query.FieldPossibleValues.getProjectIdsForQuery(FieldPossibleValues.java:38)
  ...
  	at com.atlassian.cache.compat.delegate.DelegatingCache.get(DelegatingCache.java:37)
  	at com.atlassian.greenhopper.service.query.QueryToProjectMapper.getProjectContextIdsForQuery(QueryToProjectMapper.java:78)
  	at com.atlassian.greenhopper.service.query.QueryServiceImpl.getProjectsForRapidView(QueryServiceImpl.java:116)
  	at com.atlassian.greenhopper.service.query.QueryServiceImpl.getExplicitProjectsForRapidViewFilterQuery(QueryServiceImpl.java:103)
  	at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findProjectsByRapidView(ProjectRapidViewServiceImpl.java:57)
  	at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findRapidViewsByProject(ProjectRapidViewServiceImpl.java:40)
  	at com.atlassian.greenhopper.web.sidebar.ProjectBoardsHelper.getProjectBoards(ProjectBoardsHelper.java:53)
  	at com.atlassian.greenhopper.web.sidebar.BoardScopeFilterContextProviderImpl.getContext(BoardScopeFilterContextProviderImpl.java:37)
  	at com.atlassian.greenhopper.web.sidebar.AgileBoardScopeFilterContextProvider.getContext(AgileBoardScopeFilterContextProvider.java:27)
  	at com.atlassian.jira.projects.context.ProjectContextPopulator.populateWithProject(ProjectContextPopulator.java:77)
  ...
  

Known slow tasks causing slow getProjectContextIdsForQuery population

• loading data for getVersionsByName cache from DB which is slow for large number of version:

  "http-bio-80-exec-121" #345 daemon prio=5 os_prio=0 tid=0x00000000342d3800 nid=0x1130 runnable [0x0000000262a98000]
     java.lang.Thread.State: RUNNABLE
  	at java.net.SocketInputStream.socketRead0(Native Method)
  ...
  	at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207)
  ...
  	at org.ofbiz.core.entity.GenericDelegator.findAll(GenericDelegator.java:802)
  	at com.atlassian.jira.ofbiz.DefaultOfBizDelegator.findAll(DefaultOfBizDelegator.java:361)
  ...
  	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3573)
  ...
  	at com.atlassian.jira.project.version.CachingVersionStore.getVersionsByName(CachingVersionStore.java:148)
  	at com.atlassian.jira.project.version.DefaultVersionManager.getVersionsByName(DefaultVersionManager.java:577)
  	at com.atlassian.jira.jql.resolver.VersionResolver.getIdsFromName(VersionResolver.java:30)
  ...
          com.atlassian.greenhopper.service.query.FieldPossibleValuesAdapterImpl.possibleValuesForIssueInput(FieldPossibleValuesAdapterImpl.java:21)
  	at com.atlassian.greenhopper.service.query.FieldPossibleValues.getProjectIdsForQuery(FieldPossibleValues.java:38)
  ...
  	at com.atlassian.cache.compat.delegate.DelegatingCache.get(DelegatingCache.java:37)
  	at com.atlassian.greenhopper.service.query.QueryToProjectMapper.getProjectContextIdsForQuery(QueryToProjectMapper.java:78)
  	at com.atlassian.greenhopper.service.query.QueryServiceImpl.getProjectsForRapidView(QueryServiceImpl.java:116)
  	at com.atlassian.greenhopper.service.query.QueryServiceImpl.getExplicitProjectsForRapidViewFilterQuery(QueryServiceImpl.java:103)
  	at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findProjectsByRapidView(ProjectRapidViewServiceImpl.java:57)
  	at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findRapidViewsByProject(ProjectRapidViewServiceImpl.java:40)
  	at com.atlassian.greenhopper.web.sidebar.ProjectBoardsHelper.getProjectBoards(ProjectBoardsHelper.java:53)
  	at com.atlassian.greenhopper.web.sidebar.BoardScopeFilterContextProviderImpl.getContext(BoardScopeFilterContextProviderImpl.java:37)
  	at com.atlassian.greenhopper.web.sidebar.AgileBoardScopeFilterContextProvider.getContext(AgileBoardScopeFilterContextProvider.java:27)
  	at com.atlassian.jira.projects.context.ProjectContextPopulator.populateWithProject(ProjectContextPopulator.java:77)
  ...
  

  See JRA-62666
  This is fixed in recent version of JIRA

• expensive JQL context validation for third-party JQL statements, see JRASERVER-67570

  "http-nio-8080-exec-19 url:/browse/ABC-1 username:admin " #464 daemon prio=5 os_prio=0 tid=0x00007faed3290000 nid=0x3300 runnable [0x00007fae9738d000]
   java.lang.Thread.State: RUNNABLE
   ...
   at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1165)
   at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
  …
   at com.atlassian.jira.bc.issue.search.DefaultSearchService.validateQuery(DefaultSearchService.java:242)
  ...
   at com.onresolve.jira.groovy.jql.util.QueryValidator.validateSubquery(QueryValidator.groovy:28)
  ....
   at com.onresolve.jira.groovy.jql.relations.RelationsOfMatchingQuery.validate(RelationsOfMatchingQuery.groovy:79)
   at com.onresolve.jira.groovy.jql.JqlFunction$validate$3.call(Unknown Source)
   at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
   at com.onresolve.jira.groovy.jql.JqlFunction$validate$3.call(Unknown Source)
   at com.onresolve.jira.groovy.jql.ScriptedJqlFunction.validate(ScriptedJqlFunction.groovy:101)
   at com.atlassian.jira.jql.operand.FunctionOperandHandler$2.call(FunctionOperandHandler.java:39)
   at com.atlassian.jira.jql.operand.FunctionOperandHandler$2.call(FunctionOperandHandler.java:36)
   at com.atlassian.ozymandias.SafePluginPointAccess.call(SafePluginPointAccess.java:187)
   at com.atlassian.jira.jql.operand.FunctionOperandHandler.validate(FunctionOperandHandler.java:36)
   at com.atlassian.jira.jql.operand.FunctionOperandHandler.validate(FunctionOperandHandler.java:26)
   at com.atlassian.jira.jql.operand.DefaultJqlOperandResolver.validate(DefaultJqlOperandResolver.java:109)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.validateOperands(ValidatorVisitor.java:157)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.validateOperatorAndOperand(ValidatorVisitor.java:89)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.visit(ValidatorVisitor.java:68)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.visit(ValidatorVisitor.java:36)
   at com.atlassian.query.clause.TerminalClauseImpl.accept(TerminalClauseImpl.java:143)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.getMessagesFromSubClauses(ValidatorVisitor.java:165)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.visit(ValidatorVisitor.java:63)
   at com.atlassian.jira.jql.validator.ValidatorVisitor.visit(ValidatorVisitor.java:36)
   at com.atlassian.query.clause.OrClause.accept(OrClause.java:28)
   …
  at com.atlassian.cache.compat.delegate.DelegatingCacheLoader.load(DelegatingCacheLoader.java:23)
   at com.atlassian.cache.ehcache.LoadingCache.getFromLoader(LoadingCache.java:145)
   at com.atlassian.cache.ehcache.LoadingCache.loadValueAndReleaseLock(LoadingCache.java:100)
   at com.atlassian.cache.ehcache.LoadingCache.get(LoadingCache.java:76)
   at com.atlassian.cache.ehcache.DelegatingCache.get(DelegatingCache.java:97)
   at com.atlassian.cache.compat.delegate.DelegatingCache.get(DelegatingCache.java:37)
   at com.atlassian.greenhopper.service.query.QueryToProjectMapper.getProjectContextIdsForQuery(QueryToProjectMapper.java:78)
   at com.atlassian.greenhopper.service.query.QueryServiceImpl.getProjectsForRapidView(QueryServiceImpl.java:123)
   at com.atlassian.greenhopper.service.query.QueryServiceImpl.getExplicitProjectsForRapidViewFilterQuery(QueryServiceImpl.java:110)
   at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findProjectsByRapidView(ProjectRapidViewServiceImpl.java:69)
   at com.atlassian.greenhopper.service.rapid.ProjectRapidViewServiceImpl.findRapidViewsByProject(ProjectRapidViewServiceImpl.java:51)
   at com.atlassian.greenhopper.web.sidebar.ProjectBoardsHelper.getProjectBoards(ProjectBoardsHelper.java:53)
   at com.atlassian.greenhopper.web.sidebar.BoardScopeFilterContextProviderImpl.getContext(BoardScopeFilterContextProviderImpl.java:47)
  ...
  

Notes

Verification

Taking thread dumps as per Generate a Thread Dump during problematic periods of slowness, and searching for the below stack traces can indicate this is a problem:

grep -c 'http-bio-80-exec' thread_dump1.txt 
150

grep 'http-bio-80-exec' thread_dump1.txt | grep -c 'waiting on condition' 
145

grep -A 20 'http-bio-80-exec' thread_dump1.txt | grep -c 'getProjectContextIdsForQuery' 
145

grep 'http-bio-80-exec' thread_dump1.txt | grep runnable 
"http-bio-80-exec-37" #255 daemon prio=5 os_prio=0 tid=0x000000002b37d000 nid=0x1c48 runnable

Other notes

This actual bug is not caused by large number of version, but happy assumption in cache loader getProjectContextIdsForQuery that it will take feasible amount of time
to resolve queries
Problem with large number of versions is mitigated in JRA-62666 bug and fixed in JIRA 7.1.2 and 6.4.14

Related bugs

• loading cache getProjectContextIdsForQuery is exectuted as part of findRapidViewsByProject method, see JSWSERVER-16130
• loading cache getProjectContextIdsForQuery is done as part of board-scope-filter loading data for sidebar, see JSWSERVER-16185
• combination of those 2 bugs makes any thread which needs sidebar to render the page to also wait for this cache.

Workaround

Applicable for JIRA 6.4.x only, From JRA-45178
Use the following steps below.

1. Disable the board-scope-filter module in JIRA Agile Add-on (board-scope-filter module tells the sidebar the list of boards to show on the board dropdown as well as the board that is currently selected.). This will disable com.atlassian.greenhopper.web.sidebar.AgileBoardScopeFilterContextProvider.getContext method.
   1. Navigate through Administration menu > Add-ons > Manage Add-ons > Select 'JIRA Agile'
   2. Expand the JIRA Agile Add-on modules
   3. Find the 'board-scope-filter' module and disable it.
2. Disable Project Navigation (Sidebar project navigation) for all users: Administration Menu > System > Project Navigation