Hi,
we are supporting for our customer JIRA 4.4.1. server.
It's installed on Windows 2003 Server, using MS SQL 2005 database and JDTS 1.2.5 JDBC driver.
Following problem seems to start after we upgrade JIRA from 4.2 to 4.4.1.
Our problem is that sometimes (lets say 1-2 times a week) JIRA hangs when creating a new issue. It works fine till form with new issue is submitted. Even after that seems that everything (except create issue) works - dashboards, viewing issues etc. In log there is nothing, so we made a thread dumps after some time in that "hang" state and in all dumps there was following :
"http-192.168.147.31-443-56" daemon prio=6 tid=0x6bd06400 nid=0x854 runnable [0x71ddd000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.DataInputStream.readFully(DataInputStream.java:178)
at java.io.DataInputStream.readFully(DataInputStream.java:152)
at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:846)
at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:727)
- locked <0x2b032d00> (a java.util.ArrayList)
at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3932)
at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1046)
- locked <0x2d5200c8> (a net.sourceforge.jtds.jdbc.TdsCore)
at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQLQuery(JtdsStatement.java:465)
at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeQuery(JtdsPreparedStatement.java:776)
- locked <0x2b01e6d0> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:205)
at org.ofbiz.core.entity.jdbc.SQLProcessor.executeQuery(SQLProcessor.java:597)
at org.ofbiz.core.entity.GenericDAO.select(GenericDAO.java:497)
at org.ofbiz.core.entity.GenericDAO.select(GenericDAO.java:464)
at org.ofbiz.core.entity.GenericHelperDAO.findByPrimaryKey(GenericHelperDAO.java:78)
at org.ofbiz.core.entity.GenericDelegator.findByPrimaryKey(GenericDelegator.java:543)
at org.ofbiz.core.entity.GenericDelegator.findByPrimaryKey(GenericDelegator.java:578)
at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.atlassian.multitenant.impl.MultiTenantComponentFactoryImpl$AbstractMultiTenantAwareInvocationHandler.invokeInternal(MultiTenantComponentFactoryImpl.java:181)
at com.atlassian.multitenant.impl.MultiTenantComponentFactoryImpl$MultiTenantAwareMethodInterceptor.intercept(MultiTenantComponentFactoryImpl.java:230)
at org.ofbiz.core.entity.GenericDelegator$$EnhancerByCGLIB$$a0136d89.findByPrimaryKey(<generated>)
at com.atlassian.jira.ofbiz.DefaultOfBizDelegator.findByPrimaryKey(DefaultOfBizDelegator.java:394)
at com.atlassian.jira.project.DefaultProjectManager.getProject(DefaultProjectManager.java:265)
at com.atlassian.jira.project.DefaultProjectManager$1.getProject(DefaultProjectManager.java:81)
at com.atlassian.jira.project.DefaultProjectManager$NextIdGenerator$2.call(DefaultProjectManager.java:672)
at com.atlassian.jira.project.DefaultProjectManager$NextIdGenerator$2.call(DefaultProjectManager.java:668)
at com.atlassian.util.concurrent.ManagedLocks$ManagedLockImpl.withLock(ManagedLocks.java:324)
at com.atlassian.util.concurrent.LockManagers$Manager.withLock(LockManagers.java:107)
at com.atlassian.jira.project.DefaultProjectManager$NextIdGenerator.getNextId(DefaultProjectManager.java:667)
at com.atlassian.jira.project.DefaultProjectManager.getNextId(DefaultProjectManager.java:146)
at com.atlassian.jira.project.AbstractProjectManager.getNextId(AbstractProjectManager.java:51)
at com.atlassian.jira.project.CachingProjectManager.getNextId(CachingProjectManager.java:70)
at com.atlassian.jira.workflow.function.issue.IssueCreateFunction.execute(IssueCreateFunction.java:51)
at com.opensymphony.workflow.AbstractWorkflow.executeFunction(AbstractWorkflow.java:869)
at com.opensymphony.workflow.AbstractWorkflow.transitionWorkflow(AbstractWorkflow.java:1265)
at com.opensymphony.workflow.AbstractWorkflow.initialize(AbstractWorkflow.java:618)
at com.atlassian.jira.workflow.OSWorkflowManager.createIssue(OSWorkflowManager.java:815)
at com.atlassian.jira.issue.managers.DefaultIssueManager.createIssue(DefaultIssueManager.java:461)
at com.atlassian.jira.issue.managers.DefaultIssueManager.createIssue(DefaultIssueManager.java:383)
at com.atlassian.jira.bc.issue.DefaultIssueService.create(DefaultIssueService.java:193)
at com.atlassian.jira.bc.issue.DefaultIssueService.create(DefaultIssueService.java:207)
at com.atlassian.jira.web.action.issue.CreateIssueDetails.createIssue(CreateIssueDetails.java:95)
at com.atlassian.jira.web.action.issue.CreateIssueDetails.doExecute(CreateIssueDetails.java:71)
at webwork.action.ActionSupport.execute(ActionSupport.java:165)
at com.atlassian.jira.action.JiraActionSupport.execute(JiraActionSupport.java:76)
So it seems all creating actions (that edit database) are all locked by some running transaction which seems to be deadlocked and never ends. After restarting JIRA everything works fine for some time till simillar situation happens again and we are forced restart JIRA again.
After one JIRA restart (just once, not every time) there was in log :
2011-11-24 08:20:47,980 http-192.168.147.31-443-7 ERROR [500ErrorPage.jsp] Exception caught in 500 page org.ofbiz.core.entity.GenericEntityException: Error getting the next result (Transaction (Process ID 72) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.)
com.atlassian.crowd.embedded.ofbiz.db.DataAccessException: org.ofbiz.core.entity.GenericEntityException: Error getting the next result (Transaction (Process ID 72) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.)
at com.atlassian.crowd.embedded.ofbiz.db.OfBizHelper.findByAnd(OfBizHelper.java:51)
at com.atlassian.crowd.embedded.ofbiz.OfBizUserDao.findAttributesGenericValues(OfBizUserDao.java:296)
at com.atlassian.crowd.embedded.ofbiz.OfBizUserDao.findByNameWithAttributes(OfBizUserDao.java:115)
at com.atlassian.crowd.directory.AbstractInternalDirectory.findUserWithAttributesByName(AbstractInternalDirectory.java:126)
at com.atlassian.crowd.manager.directory.DirectoryManagerGeneric.findUserWithAttributesByName(DirectoryManagerGeneric.java:288)
at com.atlassian.crowd.manager.application.ApplicationServiceGeneric.findUserWithAttributesByName(ApplicationServiceGeneric.java:307)
at com.atlassian.crowd.embedded.core.CrowdServiceImpl.getUserWithAttributes(CrowdServiceImpl.java:109)
at com.atlassian.crowd.embedded.core.DelegatingCrowdService.getUserWithAttributes(DelegatingCrowdService.java:45)
at com.atlassian.crowd.embedded.core.FilteredCrowdServiceImpl.getUserWithAttributes(FilteredCrowdServiceImpl.java:43)
at com.atlassian.jira.security.login.LoginStoreImpl.getLoginInfo(LoginStoreImpl.java:107)
at com.atlassian.jira.security.login.LoginStoreImpl.recordLoginAttempt(LoginStoreImpl.java:82)
at com.atlassian.jira.security.login.LoginManagerImpl.recordLoginAttempt(LoginManagerImpl.java:321)
at com.atlassian.jira.security.login.LoginManagerImpl.onLoginAttempt(LoginManagerImpl.java:203)
at com.atlassian.jira.security.login.JiraElevatedSecurityGuard.onSuccessfulLoginAttempt(JiraElevatedSecurityGuard.java:34)
at com.atlassian.seraph.auth.DefaultAuthenticator.getUserFromCookie(DefaultAuthenticator.java:467)
at com.atlassian.seraph.auth.DefaultAuthenticator.getUser(DefaultAuthenticator.java:327)
at com.atlassian.seraph.filter.SecurityFilter.doFilter(SecurityFilter.java:125)
In time of that exception in SQL logs we found following :
deadlock-list
2011-11-24 08:20:46.77 spid19s deadlock victim=process3a13ac8
2011-11-24 08:20:46.77 spid19s process-list
2011-11-24 08:20:46.77 spid19s process id=process3a13ac8 taskpriority=0 logused=0 waitresource=KEY: 5:72057594052935680 (01007349e4a7) waittime=4765 ownerId=7134886092 transactionname=SELECT lasttranstarted=2011-11-24T08:20:41.990 XDES=0x1287e4558 lockMode=S schedulerid=2 kpid=14972 status=suspended spid=72 sbid=0 ecid=0 priority=0 transcount=0 lastbatchstarted=2011-11-24T08:20:41.990 lastbatchcompleted=2011-11-24T08:20:41.990 clientapp=jTDS hostname=SRV-JOULE-VPC hostpid=123 loginname=ceskyweb isolationlevel=read committed (2) xactid=7134886092 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
2011-11-24 08:20:46.77 spid19s executionStack
2011-11-24 08:20:46.77 spid19s frame procname=adhoc line=1 stmtstart=46 sqlhandle=0x020000000c9f3a043beaf7dab3dde039dde480095e466a99
2011-11-24 08:20:46.77 spid19s SELECT ID, user_id, directory_id, attribute_name, attribute_value, lower_attribute_value FROM jiraschema.cwd_user_attributes WHERE user_id= @P0 AND directory_id= @P1
2011-11-24 08:20:46.77 spid19s inputbuf
2011-11-24 08:20:46.77 spid19s (@P0 bigint,@P1 bigint)SELECT ID, user_id, directory_id, attribute_name, attribute_value, lower_attribute_value FROM jiraschema.cwd_user_attributes WHERE user_id= @P0 AND directory_id= @P1
2011-11-24 08:20:46.77 spid19s process id=process3a27978 taskpriority=0 logused=284 waitresource=KEY: 5:72057594054377472 (5f052fa34539) waittime=4765 ownerId=7134886096 transactionname=DELETE lasttranstarted=2011-11-24T08:20:42.007 XDES=0x8e4858f0 lockMode=X schedulerid=4 kpid=28560 status=suspended spid=182 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2011-11-24T08:20:42.007 lastbatchcompleted=2011-11-24T08:20:42.007 clientapp=jTDS hostname=SRV-JOULE-VPC hostpid=123 loginname=ceskyweb isolationlevel=read committed (2) xactid=7134886096 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
2011-11-24 08:20:46.77 spid19s executionStack
2011-11-24 08:20:46.77 spid19s frame procname=adhoc line=1 stmtstart=62 sqlhandle=0x0200000049aac32c40325ee16d65cdcc4256c0703d112893
2011-11-24 08:20:46.77 spid19s DELETE FROM jiraschema.cwd_user_attributes WHERE user_id= @P0 AND attribute_name= @P1
2011-11-24 08:20:46.77 spid19s inputbuf
2011-11-24 08:20:46.77 spid19s (@P0 bigint,@P1 nvarchar(4000))DELETE FROM jiraschema.cwd_user_attributes WHERE user_id= @P0 AND attribute_name= @P1
2011-11-24 08:20:46.77 spid19s resource-list
2011-11-24 08:20:46.77 spid19s keylock hobtid=72057594052935680 dbid=5 objectname=jira_4.jiraschema.cwd_user_attributes indexname=PK_cwd_user_attributes id=lockfb678600 mode=X associatedObjectId=72057594052935680
2011-11-24 08:20:46.77 spid19s owner-list
2011-11-24 08:20:46.77 spid19s owner id=process3a27978 mode=X
2011-11-24 08:20:46.77 spid19s waiter-list
2011-11-24 08:20:46.77 spid19s waiter id=process3a13ac8 mode=S requestType=wait
2011-11-24 08:20:46.77 spid19s keylock hobtid=72057594054377472 dbid=5 objectname=jira_4.jiraschema.cwd_user_attributes indexname=uk_user_attr_name_lval id=lock114e27400 mode=U associatedObjectId=72057594054377472
2011-11-24 08:20:46.77 spid19s owner-list
2011-11-24 08:20:46.77 spid19s owner id=process3a13ac8 mode=S
2011-11-24 08:20:46.77 spid19s waiter-list
2011-11-24 08:20:46.77 spid19s waiter id=process3a27978 mode=X requestType=convert
So it looks that MS SQL sometimes gets to a deadlock, or something simillar, but we are not sure because exception with related SQL log happened only once and not in other hang situations.
We are desperate because we don't know what to do :( Any help would be very appreciated.
Thank you.
Ondrej Berger
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.