jira-slow-queries.log

[Petr Lazovic]

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

 

[Volodymyr Krupach]

400ms as per Chris: https://answers.atlassian.com/questions/12256183

[Petr Lazovic]

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?

[Petr Lazovic]

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

[Petr Lazovic]

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.

[Alex Medved _ConfiForms_]

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

[Petr Lazovic]

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

[Alex Medved _ConfiForms_]

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

[Petr Lazovic]

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

[Radek Antoniuk]

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?