Bug 852451 - [engine-core] Deadlock detected in DB in deactivate 10 disks scenario.
[engine-core] Deadlock detected in DB in deactivate 10 disks scenario.
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
x86_64 Linux
unspecified Severity high
: ---
: ---
Assigned To: Eli Mesika
vvyazmin@redhat.com
infra
:
: 853724 (view as bug list)
Depends On:
Blocks: 834888
  Show dependency treegraph
 
Reported: 2012-08-28 10:17 EDT by vvyazmin@redhat.com
Modified: 2016-02-10 14:00 EST (History)
13 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-12-04 15:05:49 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
## Logs vdsm, rhevm (239.57 KB, application/x-gzip)
2012-08-28 10:17 EDT, vvyazmin@redhat.com
no flags Details

  None (edit)
Description vvyazmin@redhat.com 2012-08-28 10:17:05 EDT
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
Comment 1 Yair Zaslavsky 2012-08-29 11:15:44 EDT
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.
Comment 2 mkublin 2012-09-03 02:45:10 EDT
*** Bug 853724 has been marked as a duplicate of this bug. ***
Comment 4 vvyazmin@redhat.com 2012-09-05 05:20:19 EDT
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)
Comment 5 Eli Mesika 2012-09-11 19:46:17 EDT
http://gerrit.ovirt.org/#/c/7641/
Comment 6 Eli Mesika 2012-09-20 04:10:34 EDT
fixed in commits: 779129d, 0ef25f5, d25c7ee
Comment 9 vvyazmin@redhat.com 2012-10-04 05:48:37 EDT
Verified on RHEVM 3.1 - SI19

RHEVM: rhevm-3.1.0-18.el6ev.noarch
VDSM: vdsm-4.9.6-36.0.el6_3.x86_64
LIBVIRT: libvirt-0.9.10-21.el6_3.4.x86_64
QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.295.el6_3.2.x86_64
SANLOCK: sanlock-2.3-4.el6_3.x86_64

Note You need to log in before you can comment on or make changes to this bug.