jira-slow-queries.log

Petr Lazovic January 5, 2015

Hi, 
need your advice on how to understand atlassian-jira-slow-queries.log


From my atlassian-jira-slow-queries.log :

...took '11256' ms to run - is the highest result in milliseconds
...took '403' ms to run - is the minimum result 
...~ '1700' ms to run - most regular result

What is the ms count gotta be for jql queries to get written to this log? I mean when? 
How many times my highest result is bigger than normal? And what is a good result?

I've red that there is some issues with JQL architecture, that provides slowness but it's fixed in 6.3.x.
If I upgrade to 6.3. will it help? Any examples from real life will be appreciated.

Thanx. 

JIRA: 5.0.4
Oracle Linux, VM, RAM 2Gb, Issues: 240k, projects: 4, users: 500 active (~20 concurrent a day), groups: 20, workflows: 6 active, + 15-20k issues a month

 

9 answers

1 vote
Volodymyr Krupach
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
February 3, 2015
0 votes
Petr Lazovic January 28, 2015

Please, can anyone explain when results of slow queries get into atlassian-jira-slow-queries.log file?
Hitting what ms limit queries are considered to be slow?
If [3674ms] - /browse/ABC-204911 is slow, what is normal browsing time?

0 votes
Petr Lazovic January 8, 2015

( started a separate topic on profiling - https://answers.atlassian.com/questions/11974637/jira-profiling )

0 votes
Petr Lazovic January 8, 2015

Sash, thank you for the tip. I hope to get the results of JVM stats soon. But can you say how bad are the results: ...took '11256' ms to run - ...took '403' ms to run - ...~ '1700' ms to run - And how bad bad are the results of JIRA profiling: [868ms] - /jira/secure/IssueNavigator!executeAdvanced.jspa [66ms] - IssueNavigator.execute() [18ms] - PermissionManager.getProjectObjects() [22ms] - Lucene Search [604ms] - IssueTableHtml another user: [224ms] - /secure/WorkflowUIDispatcher.jspa [34ms] - WorkflowUIDispatcher.execute() [4ms] - PermissionManager.hasPermission() [4ms] - PermissionManager.hasPermission() [5ms] - PermissionManager.hasPermission() [5ms] - PermissionManager.hasPermission() [0ms] - PermissionManager.hasPermission() [176ms] - SimpleWorkflowAction.execute() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [0ms] - IssueIndexManager.reIndex() [0ms] - IssueIndexManager.reIndexIssueObjects() [86ms] - IssueIndexManager.reIndex() [548ms] - /browse/ABC-112835 [472ms] - QuickLinkServlet.service() [40ms] - ViewIssue.execute() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [2ms] - PermissionManager.hasPermission() [11ms] - Updating Pager for viewing issue:ABC-112835 [109ms] - /secure/CommentAssignIssue!default.jspa [34ms] - CommentAssignIssue.execute() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [2ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [2ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [2ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [0ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [2ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [3ms] - PermissionManager.hasPermission() [1ms] - PermissionManager.hasPermission() one more: [817ms] - /plugins/servlet/streams [671ms] - /secure/IssueNavigator.jspa [252ms] - IssueNavigator.execute() [3674ms] - /browse/ABC-204911 [3621ms] - QuickLinkServlet.service() [33ms] - ViewIssue.execute() [3ms] - PermissionManager.hasPermission() [0ms] - PermissionManager.hasPermission() [1ms] - PermissionManager.hasPermission() [1ms] - PermissionManager.hasPermission() [0ms] - Updating Pager for viewing issue:ABC-204911 [557ms] - IssueTableHtml Thank you.

0 votes
Alex Medved _ConfiForms_
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
January 5, 2015

Is it when you run your slow queries? And java uses 1.1g, actually 768M... you have no stats for what is going on in JAVA VM... Try something like http://docs.oracle.com/javase/7/docs/technotes/tools/share/jmap.html to get inside the JVM and see what is going on

0 votes
Petr Lazovic January 5, 2015

I've got 37.7% of RAM free (free -m): total used free shared buffers cached Mem: 2001 1984 16 0 21 718 -/+ buffers/cache:1245 755 Swap: 1023 35 988 ----------------------------------------------- And the following: %CPU %MEM COMMAND 9.9 54.9 /usr/bin/java ---------------------------------------------- top - 10:47:01 up 32 days, 17:29, 2 users, load average: 0.00, 0.00, 0.00 Tasks: 91 total, 1 running, 90 sleeping, 0 stopped, 0 zombie Cpu(s): 2.5%us, 0.3%sy, 0.0%ni, 97.2%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 2049188k total, 2033936k used, 15252k free, 22652k buffers Swap: 1048568k total, 36408k used, 1012160k free, 729612k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 11191 xxx 20 0 2292m 1.1g 8204 S 10.0 55.0 1098:43 java ------------------------------------------------------------------------------------------------------------------------------ vmstat -S M 1 10 procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 35 16 22 711 0 0 6 20 4 2 3 1 96 0 0 0 0 35 16 22 711 0 0 0 0 140 252 0 0 100 0 0 1 0 35 16 22 711 0 0 0 16 156 261 0 0 99 0 0 1 0 35 16 22 711 0 0 0 0 134 250 0 0 100 0 0 0 0 35 16 22 711 0 0 0 108 162 264 0 0 100 0 0 0 0 35 16 22 711 0 0 0 0 228 280 1 0 100 0 0 0 0 35 16 22 711 0 0 0 0 1125 468 15 3 82 0 0 1 0 35 16 22 711 0 0 0 0 174 261 0 0 100 0 0 0 0 35 16 22 711 0 0 0 0 136 259 0 0 100 0 0 0 0 35 16 22 711 0 0 0 12 138 257 0 0 100 0 0

0 votes
Alex Medved _ConfiForms_
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
January 5, 2015

Xmx768m seems quite low. Check the JIRA "health", aka memory usage before trying to "tune" the database

0 votes
Petr Lazovic January 5, 2015

Hi, Radoslav We are on Oracle 11g, our data base runs on a separate machine. JVM: MaxPermSize=256m -Xms256m -Xmx768m

0 votes
Radek Antoniuk
Rising Star
Rising Star
Rising Stars are recognized for providing high-quality answers to other users. Rising Stars receive a certificate of achievement and are on the path to becoming Community Leaders.
January 5, 2015

I'm not going to elaborate on the times, because tuning database is a complicated matter in any application... but just out of curiosity... Are you running both: JIRA and MySQL on the same host? If yes, 2GB of RAM seems a bit too low for that number of users and issues/month. What are your JAVA memory settings and innodb_pool_size settings?

Suggest an answer

Log in or Sign up to answer