Intermittent slow operations in Jira

[steve_atkinson]

We're seeing some issues with our Jira instance running in a Docker container and connecting to an Oracle database, where some operations intermittently take 103-105 seconds. The rest of the time the operations are fast.

We've used the com.atlassian.util.benchmark.JIRASQLPerformance tool mentioned on this page  https://confluence.atlassian.com/jirakb/testing-database-access-speed-54362302.html

It always seems to pause after 241 - 243 iterations for around 103-105 seconds before continuing on for the remainder of the 1000 iterations. Apart from the one isolated operation that takes the significant amount of time the rest are all fast enough.

It's not always the same operation the takes the time, we've seen it for these ones retrieve-custom-field-value, retrieve-issue, retrieve-workflow

I've turned on HTTP Access and SQL logging in JIRA itself and we see the same 103-105 seconds duration for different operations on the application itself.

Anyone got any ideas for where to look further for the cause of this issue?

[Mizan]

Can you please answer below

1. What are these slow operations , can you give some details 

2. How frequent this happens and since when, will it be possible to take an external thread dump while JIRA becomes slow .

3. During these 100+ seconds what happens to other operations ? is the slowness observed instance wide to all users or only for a specific operation ?

If this affects all users using the instance, I would suggest checking GC logs , if not enabled you can enable them and look out for FULL GC 

Troubleshooting performance issue is not straight forward. However, Thread dumps and GC logs can give us a good insight on the issue

My weekend starts today I wont be able to reply soon, but you can try the below if the allocated heap memory to JIRA is less than 2 GB try setting it to 2 GB i.e. -Xmx and -Xms to 2g , this can be done from jira_installation/bin/setenv.sh file 

[Steve Atkinson]

1. From the access logs over the last day or so it shows the list of requests at the bottom of the messages as  being slow. The number at the start is the number of occurrences of that particular request that were slow.

2. I'll see if I can get a thread dump if I can catch it when it happens 

3. The slowness seems to be for isolated calls from browser to server. i.e a single users browser may make multiple calls to populate the different panels and issues on a board, but only one of them takes the significant amount of time, the rest all respond quickly. And at the same time other users are accessing Jira with no problems at all.

Occasionally, different users may have the same experience, i.e. one of the calls from their different browsers is slow, while the other calls at the same time are normal. 

I checked the GC logs. We had turned the heap up to 2G when on the previous version of JIRA, but that update to setenv.sh got missed during the upgrade.

We were seeing fairly regular Full GC but only ones that take 1 or 2 seconds, not ones that take over 100s.

I have updated it again last night, and the Full GC has nearly eliminated; a few durign startup, and then only one in the last 18 hours, but I am still seeing intermittent slow calls this morning the same as before the GC changes

1 /browse/GAE-65
1 /browse/SOEPNXQA-11
1 /browse/TFT-516
1 /rest/api/2/issue/13832/subtask/move
8 /rest/api/2/issue/picker
1 /rest/api/latest/user/assignable/search
1 /rest/dev-status/1.0/issue/stale-issues
2 /rest/dev-status/1.0/issue/summary
3 /rest/greenhopper/1.0/sprint/rank
1 /rest/greenhopper/1.0/xboard/issue/details/details
13 /rest/greenhopper/1.0/xboard/issue/details.json
10 /rest/greenhopper/1.0/xboard/plan/backlog/data.json
9 /rest/greenhopper/1.0/xboard/work/allData.json
1 /rest/project-templates/1.0/templates
2 /secure/admin/ViewSystemInfo.jspa
3 /secure/AjaxIssueAction!default.jspa
1 /secure/AjaxIssueAction.jspa
1 /secure/AjaxIssueEditAction!default.jspa
1 /secure/ConvertSubTaskConvert.jspa
1 /secure/DetailsViewAjaxIssueAction.jspa
2 /secure/GHGoToBoard.jspa
3 /secure/QuickCreateIssue.jspa
1 /secure/QuickEditIssue.jspa
2 /secure/WorkflowUIDispatcher.jspa
 

[Mizan]

So this may not be a memory issue.

100 seconds is a lot of time for these requests. What were the recent changes done on JIRA . Did you install any add-on.

Are you using any reverse proxy ?

Can you ensure you are not impacted by this , I suspect you are not using NOI and BIO is causing this

https://jira.atlassian.com/browse/JRASERVER-62745

[Steve Atkinson]

Yes, we are using reverse proxy. 

We're using Jira 7.5.0 so if I read that issue correctly the use of NIO or BIO shouldn't be affecting us as it was fixed in 7.3.0, which was the version we were using before I upgraded to 7.5.0 to see if that resolved the problem we are seeing, i.e. we were seeing the intermittent slow request in both version 7.3.0 and 7.5.0

I see the same duration of delay in one iteration (242 in the fragment below) when running the database benchmark tool, which runs standalone outside of Tomcat

Benchmark: JIRA SQL: jdbc:oracle:thin:@//......

# retrieve-issue get-issue retrieve-workflow get-workflow retrieve-custom-field-value get-custom-field-value
0 31,745,845 8,418,640 4,543,946 204,349 2,084,790 186,066
1 6,287,975 351,819 15,988,177 177,309 2,084,152 172,793
2 2,196,395 345,121 3,918,294 173,620 2,465,126 155,978
3 2,221,105 557,835 6,336,782 159,062 1,832,083 170,599
4 2,224,824 418,687 2,358,519 156,552 1,943,315 154,165
5 2,023,657 377,336 2,660,768 175,233 2,687,176 166,361

241 1,959,677 168,769 2,008,795 73,850 1,852,165 73,863
242 1,961,429 192,916 103,740,341,579 162,992 2,164,068 78,474
243 2,286,128 178,090 2,926,292 77,721 3,884,616 79,882

995 1,769,611 79,567 1,907,528 36,813 2,034,270 35,538
996 2,115,322 78,201 1,946,795 37,127 2,055,872 46,200
997 2,557,614 68,817 2,224,808 39,541 1,907,588 35,506
998 1,961,407 80,540 1,893,375 48,496 2,040,883 50,024
999 2,210,110 188,335 1,897,955 38,000 4,126,431 47,407

TOTALS
---- ---- ---- ---- ----
stat mean median min max
---- ---- ---- ---- ----
retrieve-issue 2,289,091 2,063,893 1,708,606 31,745,845
get-issue 194,404 124,400 64,019 13,625,407
retrieve-workflow 105,857,590 2,006,735 1,648,273 103,740,341,579
get-workflow 77,035 63,552 34,801 2,184,998
retrieve-custom-field-value 2,067,199 1,969,682 1,679,869 10,960,532
get-custom-field-value 94,841 60,835 33,861 17,919,877
---- ---- ---- ---- ----
All times are in nanoseconds.

[Steve Atkinson]

Following on from this observation I wrote a very simple test using java to open a JDBC connection and repeatedly run a simple sql query (select 1 from dual;) on the same connection and it exhibits a similar duration of delay (i.e. 103-5 seconds) consistently after 700 executions of the query. Does this sound familiar with anyone connecting JIRA server to a remote Oracle instance?

The details for our Oracle are:

Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics, Real Application Testing and Unified Auditing options