Fields updated at vm_device while at VdsUpdateRuntimeInfo:
imeInfo
address,alias
Fields update at HotplugDisk:
setBootOrder
We should have stored-procedures for updating only these fields in these two flows.
In addition, we should sort the vm devices , prior to storing in order to prevent the dead lock.
*** Bug 853724 has been marked as a duplicate of this bug. ***
Comment 4vvyazmin@redhat.com
2012-09-05 09:20:19 UTC
On verification run also scenario from BZ853724
Steps to Reproduce:
1. Create 20 Direct LUN's (from DL-01 till DL-20) , when the lun does not have the share tag
2. Create 2 VM's with OS installed & power on
3. Attached all 20 Direct LUN's to first VM (from DL-01 till DL-20)
4. Attached 10 Direct LUN's to second VM (from DL-11 till DL-20)
Created attachment 607588 [details] ## Logs vdsm, rhevm Description of problem: Deadlock detected in DB in deactivate 10 disks scenario. Version-Release number of selected component (if applicable): Verified on RHEVM 3.1 - SI15.1 RHEVM: rhevm-3.1.0-13.el6ev.noarch VDSM: vdsm-4.9.6-30.0.el6_3.x86_64 LIBVIRT: libvirt-0.9.10-21.el6.x86_64 QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.298.el6_3.x86_64 SANLOCK: sanlock-2.3-3.el6_3.x86_64 How reproducible: not measured Steps to Reproduce: 1. On iSCSI DC, create VM with 1 Thin-Provision bootable disk & 10 Prealocated disks 2. Install RHEL 6.3 on VM 3. Deactivate 10 disks (HotUnPlugDisk) Actual results: Deadlock detected in DB Expected results: Should not be deadlock detected in DB Additional info: /var/log/ovirt-engine/engine.log 2012-08-28 15:32:12,856 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugDiskVDSCommand] (pool-4-thread-50) [53b28896] START, HotPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 6d25793c-d9dd-4c05-ba34-42caffab139b), log id: 66434adc 2012-08-28 15:32:13,120 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotPlugDiskVDSCommand] (pool-4-thread-50) [53b28896] FINISH, HotPlugDiskVDSCommand, log id: 66434adc 2012-08-28 15:32:13,129 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-4-thread-50) [53b28896] No severity for USER_ATTACH_DISK_TO_VM type 2012-08-28 15:32:19,706 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-38) [5deaa492] START, FullListVdsCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vds=null, vmIds=[ad3cf3a6-59d0-4272-ad2d-6ddec168adf0]), log id: 19ff44c7 2012-08-28 15:32:19,740 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-38) [5deaa492] FINISH, FullListVdsCommand, return: [Lorg.ovirt.engine.core.vdsbroker.xmlrpc.XmlRpcStruct;@45fc7226, log id: 19ff44c7 2012-08-28 15:34:51,907 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-43) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 1/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,911 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-50) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 2/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,915 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-44) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 3/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,919 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-48) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 4/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,953 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-42) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 5/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,954 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-47) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 6/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,954 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-49) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 7/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,955 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-41) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 8/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,955 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-45) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 9/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:51,955 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-46) Start time: 8/28/12 3:34 PM. Start running CanDoAction for command number 10/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,529 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-44) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 3/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,540 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-43) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 1/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,543 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-45) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 9/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,545 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-46) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 10/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,547 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-50) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 2/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,547 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-48) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 4/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,551 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-41) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 8/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,639 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-47) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 6/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,775 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-49) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 7/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,777 INFO [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-42) End time: 8/28/12 3:34 PM. Finish handling CanDoAction for command number 5/10 (Command type: HotUnPlugDiskFromVm) 2012-08-28 15:34:52,779 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [67d5cce8] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:52,781 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [67d5cce8] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = b3ec311f-8ffd-459b-9cef-66d8236f51a7), log id: 5708ed8a 2012-08-28 15:34:53,553 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [67d5cce8] FINISH, HotUnPlugDiskVDSCommand, log id: 5708ed8a 2012-08-28 15:34:53,695 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [57fc89a] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:53,698 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [57fc89a] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 17a842c6-3f67-429c-a86f-35141136542c), log id: 910be78 2012-08-28 15:34:54,334 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [57fc89a] FINISH, HotUnPlugDiskVDSCommand, log id: 910be78 2012-08-28 15:34:54,520 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [84af948] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:54,523 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [84af948] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 2e6657bf-1bf6-4b38-ba10-9b4ac5a642b0), log id: 31b038dc 2012-08-28 15:34:54,870 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-51) START, FullListVdsCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vds=null, vmIds=[ad3cf3a6-59d0-4272-ad2d-6ddec168adf0]), log id: 4172bd49 2012-08-28 15:34:54,903 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-51) FINISH, FullListVdsCommand, return: [Lorg.ovirt.engine.core.vdsbroker.xmlrpc.XmlRpcStruct;@53e92530, log id: 4172bd49 2012-08-28 15:34:54,919 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-51) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=17a842c6-3f67-429c-a86f-35141136542c,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:34:54,919 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-51) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=b3ec311f-8ffd-459b-9cef-66d8236f51a7,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:34:54,988 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [84af948] FINISH, HotUnPlugDiskVDSCommand, log id: 31b038dc 2012-08-28 15:34:56,075 INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (QuartzScheduler_Worker-51) transaction rolled back 2012-08-28 15:34:56,076 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-51) ResourceManager::refreshVdsRunTimeInfo: Error: DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatevmdevice(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement, vds = 357666a8-f053-11e1-b63d-001a4a169738 : Cougar08 2012-08-28 15:34:56,077 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-51) DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatevmdevice(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement: org.springframework.dao.DeadlockLoserDataAccessException: CallableStatementCallback; SQL [{call updatevmdevice(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" 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:28) [engine-dal.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo$4.runInTransaction(VdsUpdateRunTimeInfo.java:205) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo$4.runInTransaction(VdsUpdateRunTimeInfo.java:201) [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:200) [engine-vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.saveVmDevicesToDb(VdsUpdateRunTimeInfo.java:160) [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:275) [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:] at org.ovirt.engine.core.vdsbroker.VdsManager.OnTimer(VdsManager.java:215) [engine-vdsbroker.jar:] at sun.reflect.GeneratedMethodAccessor84.invoke(Unknown Source) [:1.7.0_05-icedtea] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea] at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea] at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:64) [engine-scheduler.jar:] at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz-2.1.2.jar:] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz-2.1.2.jar:] Caused by: org.postgresql.util.PSQLException: ERROR: deadlock detected Detail: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Hint: See server log for query details. Where: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1795) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:479) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:367) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:360) at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.execute(CachedPreparedStatement.java:297) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.execute(WrappedPreparedStatement.java:404) at org.springframework.jdbc.core.JdbcTemplate$6.doInCallableStatement(JdbcTemplate.java:1066) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate$6.doInCallableStatement(JdbcTemplate.java:1) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:1014) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] ... 26 more 2012-08-28 15:34:56,161 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [7233ea38] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:56,167 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [7233ea38] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = ed4d9902-066f-48f0-b1ce-e2155b0ecfa1), log id: 73b3089e 2012-08-28 15:34:56,616 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [7233ea38] FINISH, HotUnPlugDiskVDSCommand, log id: 73b3089e 2012-08-28 15:34:56,736 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [2e563d1b] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:56,738 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [2e563d1b] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 40c5d9c7-bc55-4a6d-9e6f-a68371707a57), log id: 70377fe6 2012-08-28 15:34:57,192 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [2e563d1b] FINISH, HotUnPlugDiskVDSCommand, log id: 70377fe6 2012-08-28 15:34:57,332 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [1fc5cf61] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:57,350 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [1fc5cf61] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = b947f3cd-9bfa-4954-92e6-c5e23c34e256), log id: 73686aca 2012-08-28 15:34:57,806 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [1fc5cf61] FINISH, HotUnPlugDiskVDSCommand, log id: 73686aca 2012-08-28 15:34:57,912 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [73b1f992] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:57,913 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [73b1f992] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 428e0670-5e77-4a0e-8c09-d63d77b1bf9a), log id: 52cb4d5f 2012-08-28 15:34:58,367 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [73b1f992] FINISH, HotUnPlugDiskVDSCommand, log id: 52cb4d5f 2012-08-28 15:34:58,474 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [29781b95] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:58,476 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [29781b95] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 2081c089-919d-4bee-a2d6-7a8acb98b113), log id: 465cb93d 2012-08-28 15:34:58,929 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [29781b95] FINISH, HotUnPlugDiskVDSCommand, log id: 465cb93d 2012-08-28 15:34:59,029 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [c5ae878] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:59,031 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [c5ae878] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = fd91baf7-e87e-4d03-a185-46c6df216ffd), log id: 665f657 2012-08-28 15:34:59,465 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [c5ae878] FINISH, HotUnPlugDiskVDSCommand, log id: 665f657 2012-08-28 15:34:59,579 INFO [org.ovirt.engine.core.bll.HotUnPlugDiskFromVmCommand] (pool-4-thread-42) [2454249e] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 Type: VM 2012-08-28 15:34:59,581 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [2454249e] START, HotUnPlugDiskVDSCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0, volumeId = 6d25793c-d9dd-4c05-ba34-42caffab139b), log id: c21927e 2012-08-28 15:35:00,000 INFO [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-61) Autorecovering hosts is disabled, skipping 2012-08-28 15:35:00,000 INFO [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-61) Autorecovering storage domains is disabled, skipping 2012-08-28 15:35:00,017 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (pool-4-thread-42) [2454249e] FINISH, HotUnPlugDiskVDSCommand, log id: c21927e 2012-08-28 15:35:06,434 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-64) START, FullListVdsCommand(vdsId = 357666a8-f053-11e1-b63d-001a4a169738, vds=null, vmIds=[ad3cf3a6-59d0-4272-ad2d-6ddec168adf0]), log id: 12974b77 2012-08-28 15:35:06,464 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-64) FINISH, FullListVdsCommand, return: [Lorg.ovirt.engine.core.vdsbroker.xmlrpc.XmlRpcStruct;@adb7b2a, log id: 12974b77 2012-08-28 15:35:06,477 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=b3ec311f-8ffd-459b-9cef-66d8236f51a7,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,478 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=6d25793c-d9dd-4c05-ba34-42caffab139b,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,478 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=fd91baf7-e87e-4d03-a185-46c6df216ffd,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,478 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=b947f3cd-9bfa-4954-92e6-c5e23c34e256,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,478 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=2081c089-919d-4bee-a2d6-7a8acb98b113,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,479 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=2e6657bf-1bf6-4b38-ba10-9b4ac5a642b0,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,483 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=ed4d9902-066f-48f0-b1ce-e2155b0ecfa1,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,484 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=17a842c6-3f67-429c-a86f-35141136542c,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,484 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=40c5d9c7-bc55-4a6d-9e6f-a68371707a57,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= 2012-08-28 15:35:06,485 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-64) VM ad3cf3a6-59d0-4272-ad2d-6ddec168adf0 managed non pluggable device was removed unexpectedly from libvirt: VmId=ad3cf3a6-59d0-4272-ad2d-6ddec168adf0,DeviceId=428e0670-5e77-4a0e-8c09-d63d77b1bf9a,Device=disk,Type=disk,BootOrder=0,SpecParams={},Address=,IsManaged=true,IsPlugged=false,IsReadOnly=false,alias= /var/lib/pgsql/data/pg_log/postgresql-Tue.log LOG: autovacuum: found orphan temp table "pg_temp_6"."tt_temp22" in database "engine" LOG: autovacuum: found orphan temp table "pg_temp_6"."tt_vm_pool_group" in database "engine" ERROR: deadlock detected DETAIL: Process 8762 waits for ShareLock on transaction 1710756; blocked by process 8760. Process 8760 waits for ShareLock on transaction 1710761; blocked by process 8762. Process 8762: select * from updatevmdevice($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) as result Process 8760: select * from updatevmdevice($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) as result HINT: See server log for query details. CONTEXT: SQL statement "UPDATE vm_device SET device = $1 , type = $2 , address = $3 , boot_order = $4 , spec_params = $5 , is_managed = $6 , is_plugged = $7 , is_readonly = $8 , alias = $9 , _update_date = current_timestamp WHERE device_id = $10 and vm_id = $11 " PL/pgSQL function "updatevmdevice" line 2 at SQL statement STATEMENT: select * from updatevmdevice($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) as result WARNING: pgstat wait timeout WARNING: pgstat wait timeout