Created attachment 696087[details]
logs
Description of problem:
I created a pool of 10 vm's and ran tham -> started creating a live snapshot for each vm
we failed on a snapshot with:
EndAction for action type CreateAllSnapshotsFromVm threw an exception: org.springframework.j
dbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction
and than we get a deadlock:
2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Version-Release number of selected component (if applicable):
si27
How reproducible:
Steps to Reproduce:
1. create a pool of 10 vms with iscsi storage
2. run the vms on two hosts
3. start creating live snapshot for each vm (one at a time)
Actual results:
2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Expected results:
we should not get a deadlock
Additional info: logs
2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 "
PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 "
PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement, vds = 5d82a420-743a-11e2-a041-001a4a16971d : cougar01
2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 "
PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 "
PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement: org.springframework.dao.DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 "
PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected
Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636.
Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201.
Hint: See server log for query details.
Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 "
PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:265) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:1030) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.springframework.jdbc.core.JdbcTemplate.call(JdbcTemplate.java:1064) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.springframework.jdbc.core.simple.AbstractJdbcCall.executeCallInternal(AbstractJdbcCall.java:388) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.springframework.jdbc.core.simple.AbstractJdbcCall.doExecute(AbstractJdbcCall.java:351) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.springframework.jdbc.core.simple.SimpleJdbcCall.execute(SimpleJdbcCall.java:181) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeImpl(SimpleJdbcCallsHandler.java:124) [engine-dal.jar:]
at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeModification(SimpleJdbcCallsHandler.java:37) [engine-dal.jar:]
at org.ovirt.engine.core.dao.MassOperationsGenericDaoDbFacade.updateAll(MassOperationsGenericDaoDbFacade.java:45) [engine-dal.jar:]
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo$4.runInTransaction(VdsUpdateRunTimeInfo.java:226) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo$4.runInTransaction(VdsUpdateRunTimeInfo.java:222) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:204) [engine-utils.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:142) [engine-utils.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:109) [engine-utils.jar:]
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.updateAllInTransaction(VdsUpdateRunTimeInfo.java:221) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.updateAllInTransaction(VdsUpdateRunTimeInfo.java:199) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.SaveDataToDb(VdsUpdateRunTimeInfo.java:155) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.Refresh(VdsUpdateRunTimeInfo.java:297) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.vdsbroker.VdsManager$1.runInTransaction(VdsManager.java:234) [engine-vdsbroker.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:168) [engine-utils.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:107) [engine-utils.jar:]
:
sf 13.1
Created a pool of 10 vm's and ran them -> started creating a live snapshot for each vm. Did it several times. Snapshot were created successfully.
Created attachment 696087 [details] logs Description of problem: I created a pool of 10 vm's and ran tham -> started creating a live snapshot for each vm we failed on a snapshot with: EndAction for action type CreateAllSnapshotsFromVm threw an exception: org.springframework.j dbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction and than we get a deadlock: 2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Version-Release number of selected component (if applicable): si27 How reproducible: Steps to Reproduce: 1. create a pool of 10 vms with iscsi storage 2. run the vms on two hosts 3. start creating live snapshot for each vm (one at a time) Actual results: 2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Expected results: we should not get a deadlock Additional info: logs 2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 " PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 " PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement, vds = 5d82a420-743a-11e2-a041-001a4a16971d : cougar01 2013-02-11 14:28:58,419 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-66) DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 " PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 " PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement: org.springframework.dao.DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatedisk_image_dynamic(?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 " PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 5201 waits for ShareLock on transaction 10843; blocked by process 5636. Process 5636 waits for ShareLock on transaction 10863; blocked by process 5201. Hint: See server log for query details. Where: SQL statement "UPDATE disk_image_dynamic SET read_rate = $1 ,write_rate = $2 ,actual_size = $3 ,read_latency_seconds = $4 ,write_latency_seconds = $5 ,flush_latency_seconds = $6 WHERE image_id = $7 " PL/pgSQL function "updatedisk_image_dynamic" line 2 at SQL statement at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:265) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:1030) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.call(JdbcTemplate.java:1064) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.simple.AbstractJdbcCall.executeCallInternal(AbstractJdbcCall.java:388) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.simple.AbstractJdbcCall.doExecute(AbstractJdbcCall.java:351) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.simple.SimpleJdbcCall.execute(SimpleJdbcCall.java:181) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeImpl(SimpleJdbcCallsHandler.java:124) [engine-dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeModification(SimpleJdbcCallsHandler.java:37) [engine-dal.jar:] at org.ovirt.engine.core.dao.MassOperationsGenericDaoDbFacade.updateAll(MassOperationsGenericDaoDbFacade.java:45) [engine-dal.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo$4.runInTransaction(VdsUpdateRunTimeInfo.java:226) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo$4.runInTransaction(VdsUpdateRunTimeInfo.java:222) [engine-vdsbroker.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:204) [engine-utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:142) [engine-utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:109) [engine-utils.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.updateAllInTransaction(VdsUpdateRunTimeInfo.java:221) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.updateAllInTransaction(VdsUpdateRunTimeInfo.java:199) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.SaveDataToDb(VdsUpdateRunTimeInfo.java:155) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.Refresh(VdsUpdateRunTimeInfo.java:297) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsManager$1.runInTransaction(VdsManager.java:234) [engine-vdsbroker.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:168) [engine-utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:107) [engine-utils.jar:] :