CPU spikes causing performance issues

[Darla Sheehan]

Jira performance slowed to a stop a few times and these were found in the application log during those times. The CPU jumps corresponded with these times.

What exactly is "Rendering navigable field"? From what I can see this is a dashboard gadget which shows overviews of the tickets listed in the logs. Isn't using dashboards to display tickets in a list normal behavior for a JIRA environment?

2017-09-20 13:08:31,074 http-nio-8080-exec-209 DEBUG name@nameplc.com 787x7978390x56 17oj60z 212.44.19.221,192.168.128.152 /rest/issueNav/1/issueTable [c.a.util.profiling.UtilTimerLogger] [19959ms] -
IssueTableHtml
[0ms] - Rendering navigable field 'issuetype' for issue: ISEMSERV-14
[0ms] - Rendering navigable field 'issuekey' for issue: ISEMSERV-14
[1ms] - Rendering navigable field 'summary' for issue: ISEMSERV-14
[0ms] - Rendering navigable field 'assignee' for issue: ISEMSERV-14
[1ms] - Rendering navigable field 'reporter' for issue: ISEMSERV-14
[325ms] - Rendering navigable field 'priority' for issue: ISEMSERV-14

2017-09-20 14:20:13,993 http-nio-8080-exec-171 DEBUG name.@nameplc.com 858x8022925x63 ur7fhe 217.169.132.98,192.168.128.152 /issues/ [c.a.util.profiling.UtilTimerLogger] [79111ms] - IssueNavAction.execut
e()
[438ms] - DefaultSearchService.validateQuery()
[0ms] - DefaultJqlOperandResolver.getValues() - multivalue
[0ms] - MultiValueOperandHandler.getValues()
[0ms] - DefaultJqlOperandResolver.getValues() - multivalue
[0ms] - MultiValueOperandHandler.getValues()
[57484ms] - Searching and sorting with Collector
[2442ms] - Permission Query
[0ms] - DefaultJqlOperandResolver.getValues() - multivalue
[0ms] - MultiValueOperandHandler.getValues()
[1ms] - DefaultJqlOperandResolver.getValues() - multivalue
[1ms] - MultiValueOperandHandler.getValues()
[54720ms] - Lucene Search
[6423ms] - IssueTableHtml
[0ms] - Rendering navigable field 'issuetype' for issue: FT-6408
[0ms] - Rendering navigable field 'issuekey' for issue: FT-6408
[44ms] - Rendering navigable field 'summary' for issue: FT-6408

[MattS]

You have Profiling enabled, so you can expect to JIRA doing necessary work to display each field in an issue in the Issue Navigator or in an issue view screen. But from the long search time I suspect something in a JQL query or a custom field is doing a lot of work. If you have a staging instance and can reproduce the problem there, you can experiment with disabling add-ons until you find the one that provides some feature that is taking a long time to render

[Darla Sheehan]

Thanks Matt! So should I disable Profiling? Is that causing CPU strain too?

Also, what does "Rendering navigable field" mean? Searching the DB?

I found two quieries running at that time as well. Is there a way to tell whether these were displayed via a dashboard filter?

2017-09-20 14:20:04,491 http-nio-8080-exec-271 INFO name@name.com 858x8022702x61 4ascbm /browse/FT- [c.a.j.i.search.providers.LuceneSearchProvider_SLOW] JQL query '{project in ("FT", "FA", "FC", "FB")} AND {issuetype = "Support Request"} AND {status in ("In Progress (Development)", "With Customer", "Open", "Reopened", "In Progress")} AND {priority = "Critical"}' produced lucene query '+(projid:12104 projid:12200 projid:12201 projid:14603) +type:9 +(status:10000 status:10001 status:1 status:4 status:3) +priority:1' and took '80959' ms to run.

2017-09-20 14:20:06,405 http-nio-8080-exec-171 INFO jname@nameplc.com 858x8022925x63 ur7fhe /issues/ [c.a.j.i.search.providers.LuceneSearchProvider_SLOW] JQL query '{project in ("FT", "FA", "FC")} AND {status in ("In Progress (Development)", "With Customer", "Impact Assessment", "Quote Sent", "Evaluation", "Approved", "Open", "Reopened", "In Progress", "Resolved")} AND {level = "Invivo Group"} order by updated DESC,priority ASC,system ASC,key DESC,level DESC' produced lucene query '+(projid:12104 projid:12200 projid:12201) +(status:10000 status:10001 status:10002 status:10003 status:10004 status:10005 status:1 status:4 status:3 status:5) +(issue_security_level:11304 issue_security_level:12706)' and took '54719' ms to run.

[Darla Sheehan]

Thank Matt!

Should I disable profiling? Does that cause CPU strain?

Also, there were several queries found in the atlassian-jira-slow-queries.log during that time. Can I assume the design of these queries needs to be changed to stop consuming too many resources? And can I tell if these were run from a dashboard gadget or just by the individual? I just want to avoid several people running these moving forward.

2 examples:

2017-09-20 14:20:04,491 http-nio-8080-exec-271 INFO n@nplc.com 858x8022702x61 4ascbm /browse/FT- [c.a.j.i.search.providers.LuceneSearchProvider_SLOW] JQL query '{project in ("FT", "FA", "FC", "FB")} AND {issuetype = "Support Request"} AND {status in ("In Progress (Development)", "With Customer", "Open", "Reopened", "In Progress")} AND {priority = "Critical"}' produced lucene query '+(projid:12104 projid:12200 projid:12201 projid:14603) +type:9 +(status:10000 status:10001 status:1 status:4 status:3) +priority:1' and took '80959' ms to run.

2017-09-20 14:20:06,405 http-nio-8080-exec-171 INFO n@nplc.com 858x8022925x63 ur7fhe /issues/ [c.a.j.i.search.providers.LuceneSearchProvider_SLOW] JQL query '{project in ("FT", "FA", "FC")} AND {status in ("In Progress (Development)", "With Customer", "Impact Assessment", "Quote Sent", "Evaluation", "Approved", "Open", "Reopened", "In Progress", "Resolved")} AND {level = "Invivo Group"} order by updated DESC,priority ASC,system ASC,key DESC,level DESC' produced lucene query '+(projid:12104 projid:12200 projid:12201) +(status:10000 status:10001 status:10002 status:10003 status:10004 status:10005 status:1 status:4 status:3 status:5) +(issue_security_level:11304 issue_security_level:12706)' and took '54719' ms to run.

[MattS]

Profiling does add an extra load, but any query that takes 54.7s seconds to run suggests other problems. Perhaps the disk where your Lucene indexes are (jira.home/caches) is too remote from the CPU where JIRA is running? Try running the queries yourself, and try without the clause about "level" to see if that's causing the slow query