jira-slow-queries.log

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

This widget could not be displayed.
This widget could not be displayed.

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?

This widget could not be displayed.

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

This widget could not be displayed.

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

This widget could not be displayed.

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

This widget could not be displayed.

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

This widget could not be displayed.

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.

This widget could not be displayed.

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

This widget could not be displayed.

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?

Suggest an answer

Log in or Sign up to answer
Community showcase
Posted Tuesday in Jira

What modern development practices are at the heart of how your team delivers software?

Hey Community mates! Claire here from the Software Product Marketing team. We all know software development changes rapidly, and it's often tough to keep up. But from our research, we've found the h...

284 views 1 4
Join discussion

Atlassian User Groups

Connect with like-minded Atlassian users at free events near you!

Find a group

Connect with like-minded Atlassian users at free events near you!

Find my local user group

Unfortunately there are no AUG chapters near you at the moment.

Start an AUG

You're one step closer to meeting fellow Atlassian users at your local meet up. Learn more about AUGs

Groups near you