Loading...

Details

Type: Bug
Resolution: Unresolved
Priority: Low
Fix Version/s: None
Affects Version/s: 8.20.0, 8.13.16
Component/s: JQL
Labels:

Introduced in Version:
8.13
Support reference count:
7
Symptom Severity:
Severity 2 - Major
UIS:
3
Bug Fix Policy:
View Atlassian Server bug fix policy

Description

Issue Summary

When clicking the "Issues" menu item, Jira fetches the user's favourite filters so that they can be displayed in the menu.

As part of this lookup, Jira obtains the filter JQL and sanitises it, including checking issue key literal. Issue keys are resolved serially, which results in multiple SELECT statement against jiraissue database table. The number of statement is directly proportional to the amount of issue key literal in the JQL.

For favourite filters with many issue literal in JQL, this can slow processing so much that causes a AJAX request timeout (60 seconds) in the browser.

This affects the following endpoints (discovered so far):

/rest/api/1.0/menus/find_link
/rest/api/2/filter/favourite

Steps to Reproduce

Create some saved filter with many issue key literal in it, EG issuekey in (TEST-1, TEST-2, ...). The number to cause performance issue vary, but good start is 1000 issue keys
As a sample user, favourite that filter
Click the Issues menu

Expected Results

Issues menu loads fast

Actual Results

Issues menu loads slow, or times out.

Front end

Long running HTTP request to /rest/api/1.0/menus/find_link that times out after 60 seconds

Back end - Jira node

Thread long running on the following stack:

http-nio-8081-exec-N url: /rest/api/1.0/menus/find_link; user: S
at java.net.SocketInputStream.socketRead0(java.base@11.0.11/Native Method)
...
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
...
	at com.atlassian.jira.ofbiz.WrappingOfBizDelegator.findByAnd(WrappingOfBizDelegator.java:62)
	at com.atlassian.jira.issue.managers.DefaultIssueManager$IssueFinder.getIssueFromIssueEntityByProjectAndNumber(DefaultIssueManager.java:988)
	at com.atlassian.jira.issue.managers.DefaultIssueManager$IssueFinder.getIssueFromIssueEntity(DefaultIssueManager.java:984)
	at com.atlassian.jira.issue.managers.DefaultIssueManager$IssueFinder.getIssue(DefaultIssueManager.java:961)
	at com.atlassian.jira.issue.managers.DefaultIssueManager.getIssueByKeyIgnoreCase(DefaultIssueManager.java:347)
	at com.atlassian.jira.issue.managers.RequestCachingIssueManager.getIssueByKeyIgnoreCase(RequestCachingIssueManager.java:94)
	at com.atlassian.jira.jql.util.JqlIssueSupportImpl.getIssue(JqlIssueSupportImpl.java:70)
	at com.atlassian.jira.jql.util.JqlIssueSupportImpl.getIssue(JqlIssueSupportImpl.java:62)
	at com.atlassian.jira.jql.permission.IssueLiteralSanitiser.getIssues(IssueLiteralSanitiser.java:79)
...
	at com.atlassian.jira.issue.search.DefaultSearchRequestManager.getSearchRequests(DefaultSearchRequestManager.java:95)
	at com.atlassian.jira.bc.filter.DefaultSearchRequestService.getFavouriteFilters(DefaultSearchRequestService.java:71)
	at com.atlassian.jira.issue.search.FavouriteFilterLinkFactory.getItems(FavouriteFilterLinkFactory.java:50)
	at com.atlassian.plugin.web.DefaultWebInterfaceManager.getDynamicWebItems(DefaultWebInterfaceManager.java:249)
	at com.atlassian.plugin.web.DefaultWebInterfaceManager.getDisplayableWebItems(DefaultWebInterfaceManager.java:232)
	at com.atlassian.jira.plugin.webfragment.DefaultSimpleLinkManager.getLinksForSection(DefaultSimpleLinkManager.java:120)
	at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager.access$701(ThreadLocalCachingSimpleLinkManager.java:28)
	at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager$3.load(ThreadLocalCachingSimpleLinkManager.java:149)
	at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager$3.load(ThreadLocalCachingSimpleLinkManager.java:146)
	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3528)
	at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2277)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2154)
	- locked <0x00007f5ab9acad28> (a com.google.common.cache.LocalCache$StrongEntry)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2044)
	at com.google.common.cache.LocalCache.get(LocalCache.java:3952)
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3974)
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4958)
	at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4964)
...
	at com.atlassian.jira.rest.v1.menus.MenuResource.getMenuList(MenuResource.java:77)

While /rest/api/1.0/menus/find_link goes through cache, /rest/api/2/filter/favourite does not.

Back end - database view

With SQL debugging enabled, the excessive query count is revealed. (sample request id = 1430x1027x3)

➜  application-logs grep "1430x1027x3" atlassian-jira-sql.log* | grep "(SELECT |UPDATE |INSERT |DELETE ).*" -P -o | sed -E 's/[0-9]+/?/g' | sed -E "s/'\S+'/'?'/g" | sort | uniq -c | sort -nr
  41465 SELECT ID, pkey, issuenum, PROJECT, REPORTER, ASSIGNEE, CREATOR, issuetype, SUMMARY, DESCRIPTION, ENVIRONMENT, PRIORITY, RESOLUTION, issuestatus, CREATED, UPDATED, DUEDATE, RESOLUTIONDATE, VOTES, WATCHES, TIMEORIGINALESTIMATE, TIMEESTIMATE, TIMESPENT, WORKFLOW_ID, SECURITY, FIXFOR, COMPONENT, ARCHIVED, ARCHIVEDBY, ARCHIVEDDATE FROM jiraissue WHERE issuenum='?' AND PROJECT='?'"
  29681 SELECT ID, LINKTYPE, SOURCE, DESTINATION, SEQUENCE FROM issuelink WHERE DESTINATION='?'"
   3661 SELECT pkey, issuenum, PROJECT, REPORTER, ASSIGNEE, CREATOR, issuetype, SUMMARY, DESCRIPTION, ENVIRONMENT, PRIORITY, RESOLUTION, issuestatus, CREATED, UPDATED, DUEDATE, RESOLUTIONDATE, VOTES, WATCHES, TIMEORIGINALESTIMATE, TIMEESTIMATE, TIMESPENT, WORKFLOW_ID, SECURITY, FIXFOR, COMPONENT, ARCHIVED, ARCHIVEDBY, ARCHIVEDDATE FROM jiraissue WHERE ID='?'"
      6 SELECT NAME, DESCRIPTION, DEFAULTLEVEL FROM issuesecurityscheme WHERE ID='?'"
      6 SELECT ID, OLD_ISSUE_KEY, ISSUE_ID FROM moved_issue_key WHERE OLD_ISSUE_KEY='?'"
      4 SELECT ID, ISSUE, CUSTOMFIELD, UPDATED, PARENTKEY, STRINGVALUE, NUMBERVALUE, TEXTVALUE, DATEVALUE, VALUETYPE FROM customfieldvalue WHERE ISSUE='?'"
      1 SELECT user_name FROM cwd_user WHERE (lower_user_name =  '?' ) AND (directory_id =  '?' ) ORDER BY lower_user_name"
      1 SELECT ID, pkey, issuenum, PROJECT, REPORTER, ASSIGNEE, CREATOR, issuetype, SUMMARY, DESCRIPTION, ENVIRONMENT, PRIORITY, RESOLUTION, issuestatus, CREATED, UPDATED, DUEDATE, RESOLUTIONDATE, VOTES, WATCHES, TIMEORIGINALESTIMATE, TIMEESTIMATE, TIMESPENT, WORKFLOW_ID, SECURITY, FIXFOR, COMPONENT, ARCHIVED, ARCHIVEDBY, ARCHIVEDDATE FROM jiraissue WHERE (ID IN ('?', '?', '?', '?', '?', '?') )"

It's clear the bottleneck is the sheer number of individual SQL query sent to the DB, rather than singular query execution time, as most request execute in under 1ms:

#Below 1ms
➜  application-logs grep "1430x1027x3" atlassian-jira-sql.log* | grep "(SELECT |UPDATE |INSERT |DELETE )" -P  | grep -P '\d+?ms' -o | sort | grep -P "[0|1]ms" | sort -nr | wc -l 
72905

Workaround

Reduce the amount of issue key specified in the JQL for favourite filters, or unfavorite those filters. This is a per-user problem, as favourite filters are per-user setting.

Filters and their JQL can be found quickly via the database with:

SELECT au.lower_user_name, fa.*, sr.reqcontent FROM favouriteassociations fa 
JOIN app_user au ON fa.username = au.user_key
JOIN searchrequest sr ON fa.entityid = sr.id
WHERE fa.entitytype = 'SearchRequest';
AND au.lower_user_name = 'problematic_user_name_here';

Users having the largest amount of favorite filters having issue key literals can be found with the following SQL query (tested in MySQL):

select au.lower_user_name as username, count(*) as favorite_filters_count
from favouriteassociations fa
join searchrequest sr on sr.id = fa.entityid
join app_user au on au.user_key = fa.username
where fa.entitytype = 'SearchRequest' and lower(sr.reqcontent) regexp '[a-z]*-[0-9]*'
group by au.lower_user_name, au.user_key
order by favorite_filters_count desc;

Attachments

Issue Links

is related to

JRASERVER-65930 Favourite filters REST Resource consumes large amount of memory when user has large number of filters

Closed

JRASERVER-39358 Favourite filters REST Resource is needlessly retrieving subscriptions on Issue Navigator

Gathering Impact

mentioned in: Page Loading...

Having favourite filters with large amount of issue key literal results in Issues menu loading slowly