{"id":1697,"date":"2013-03-11T12:00:00","date_gmt":"2013-03-11T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1697"},"modified":"2013-03-11T12:00:00","modified_gmt":"2013-03-11T12:00:00","slug":"not-all-deadlocks-are-created-the-same","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2013\/03\/11\/not-all-deadlocks-are-created-the-same\/","title":{"rendered":"Not all Deadlocks are created the same"},"content":{"rendered":"

<\/code>I’ve blogged about deadlocks in Oracle<\/a> at least once before. I said then that although the following message in deadlock trace files is usually true, it isn’t always.<\/p>\n

The following deadlock is not an Oracle error. Deadlocks of\u00a0 \nthis type can be expected if certain SQL statements are\u00a0\u00a0\u00a0\u00a0\u00a0 \nissued. The following information may aid in determining the \ncause of the deadlock.\n<\/code><\/pre>\n
So when I came across another example recently, it seemed worth a quick blog post. Not least for the benefit of other souls who hit the same issue (and probably hit Google moments later).<\/p>\n
But while it’s easy to say – “Hey! Look! I found an exception! Aren’t I clever?” – it occurred to me that actually Oracle’s capabilities in this area might be underrated by raising the occasional anomaly. Because the truth is<\/p>\n
1) In most cases, deadlock errors are<\/em> down to the way you’ve written your application or some documented restriction in Oracle. The type of restrictions that you’re more likely to hit if you’re handling high degrees of concurrency with lots of DDL, parallel query, partition management and the like. Such activities often have unusually restrictive locking requirements and most locking issues can be turned into deadlock issues quite easily if you have a few sessions running concurrently. <\/p>\n
2) It’s still the case that Oracle will handle the deadlock situation, at least to the extent of rolling back one of the statements causing the issue. (Although, whilst writing this post, I noticed that Jonathan Lewis raised the question<\/a> of what exactly people mean when they suggest that Oracle resolves deadlock issues.<\/p>\n
3) Deadlock trace files are typically very useful and not the most difficult to read. Yes, they tend to use Oracle kernel terminology (not surprising) but I’d wager that most people could have a rough idea of the root cause with some initial analysis and could have a very detailed idea, given more time. Even if you can’t decipher the things yourself, it gives Oracle Support detailed information to help root cause analysis.<\/p>\n
So, to the particular issue we hit. Towards the end of a data loading process that loads around a billion rows in a short period of time (30\/60 minutes that also includes a bunch of surrounding activities), we would hit the occasional deadlock error. Fortunately, the site I’m working at just now has a very enlightened policy towards developer access to the alert log and trace files, so I can do my own initial investigation. On digging out the relevant deadlock trace file, it looked like this (some details changed)<\/p>\n
Trace file \/app\/ora\/local\/admin\/PRD\/diag\/rdbms\/PRD_prod_server\/PRD\/trace\/PRD_dia0_1627682.trc \n\nOracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production \nWith the Partitioning, Automatic Storage Management, OLAP, Data Mining \nand Real Application Testing options \nORACLE_HOME = \/app\/ora\/local\/product\/11.2.0.3\/db_1 \nSystem name:\u00a0\u00a0\u00a0 Linux \nNode name:\u00a0\u00a0\u00a0\u00a0\u00a0 prod_server.ldn.orcldoug.com \nRelease:\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2.6.32-220.13.1.el6.x86_64 \nVersion:\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 #1 SMP Thu Mar 29 11:46:40 EDT 2012 \nMachine:\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 x86_64 \nInstance name: PRD \nRedo thread mounted by this instance: 1 \nOracle process number: 8 \nUnix process pid: 1627682, image: oracle@prod_server.ldn.orcldoug.com<\/a> (DIA0)\n*** 2013-01-16 09:09:10.925 \n*** SESSION ID:(201.1) 2013-01-16 09:09:10.925 \n*** CLIENT ID:() 2013-01-16 09:09:10.925 \n*** SERVICE NAME:(SYS$BACKGROUND) 2013-01-16 09:09:10.925 \n*** MODULE NAME:() 2013-01-16 09:09:10.925 \n*** ACTION NAME:() 2013-01-16 09:09:10.925 \n\u00a0 \n------------------------------------------------------------------------------- \n\u00a0 \nDEADLOCK DETECTED (id=0xd0102292) \n\u00a0 \nChain Signature: 'library cache lock'<='row cache lock' (cycle) \nChain Signature Hash: 0x52a8007d \n\u00a0 \nThe following deadlock is not an Oracle error. Deadlocks of\u00a0 \nthis type can be expected if certain SQL statements are\u00a0\u00a0\u00a0\u00a0\u00a0 \nissued. The following information may aid in determining the \ncause of the deadlock.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \n\u00a0 \nResolving deadlock by signaling ORA-00060 to 'instance: 1, os id: 3443329, session id: 161' \n\u00a0 dump location: \/app\/ora\/local\/admin\/PRD\/diag\/rdbms\/PRD_prod_server\/PRD\/trace\/PRD_ora_3443329.trc \n\u00a0 \nPerforming diagnostic dump on 'instance: 1, os id: 3443222, session id: 779' \n\u00a0 dump location: \/app\/ora\/local\/admin\/PRD\/diag\/rdbms\/PRD_prod_server\/PRD\/trace\/PRD_ora_3443222.trc \n\u00a0 \n------------------------------------------------------------------------------- \n\u00a0\u00a0\u00a0 Oracle session identified by: \n\u00a0\u00a0\u00a0 { \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 instance: 1 (PRD_prod_server.PRD) \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 os id: 3443222 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 process id: 127, oracle@prod_server.ldn.orcldoug.com<\/a> \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 session id: 779 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 session serial #: 605 \n\u00a0\u00a0\u00a0 } \n\u00a0\u00a0\u00a0 is waiting for 'row cache lock' with wait info: \n\u00a0\u00a0\u00a0 { \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'cache id'=0x8 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'mode'=0x0 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p3: 'request'=0x5 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time in wait: 1 min 58 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 timeout after: never \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 1655 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 blocking: 1 session \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 current sql: Begin run_manager_pkg.finalize_all_values_prc(:v0); End; \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait history: \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 * time between current wait and wait #1: 0.002176 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 event: 'enq: PS - contention' \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time waited: 0.000082 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 1654\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'name|mode'=0x50530006 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'instance'=0x1 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p3: 'slave ID'=0x2f \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 * time between wait #1 and #2: 0.000013 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 event: 'PX Deq: Slave Session Stats' \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time waited: 0.000001 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 1653\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'sleeptime\/senderid'=0x0 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'passes'=0x0 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 * time between wait #2 and #3: 0.000001 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 3.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 event: 'PX Deq: Slave Session Stats' \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time waited: 0.000002 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 1652\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'sleeptime\/senderid'=0x0 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'passes'=0x0 \n\u00a0\u00a0\u00a0 } \n\u00a0\u00a0\u00a0 and is blocked by \n=> Oracle session identified by: \n\u00a0\u00a0\u00a0 { \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 instance: 1 (PRD_prod_server.PRD) \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 os id: 3443329 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 process id: 134, oracle@prod_server.ldn.orcldoug.com<\/a> \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 session id: 161 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 session serial #: 247 \n\u00a0\u00a0\u00a0 } \n\u00a0\u00a0\u00a0 which is waiting for 'library cache lock' with wait info: \n\u00a0\u00a0\u00a0 { \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'handle address'=0x101f8eac98 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'lock address'=0xfdef83738 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p3: '100*mode+namespace'=0x10f2000010003 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time in wait: 1.739719 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 timeout after: never \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 508 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 blocking: 1 session \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 current sql: ALTER INDEX \"DOUG\".\"VALUE_PK\" REBUILD PARTITION \"SYS_P4089\"
<\/p>\n
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait history: \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 * time between current wait and wait #1: 0.000973 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 event: 'enq: CR - block range reuse ckpt' \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time waited: 0.003220 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 507\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'name|mode'=0x43520006 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: '2'=0x10086 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p3: '0'=0x1 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 * time between wait #1 and #2: 0.000008 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 event: 'reliable message' \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time waited: 0.000107 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 506\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'channel context'=0x101c5afa98 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'channel handle'=0x101c0f2260 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p3: 'broadcast message'=0x101b5cfd58 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 * time between wait #2 and #3: 0.003791 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 3.\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 event: 'db file sequential read' \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 time waited: 0.000321 sec \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 wait id: 505\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p1: 'file#'=0x5e \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p2: 'block#'=0x118784 \n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 p3: 'blocks'=0x1 \n\u00a0\u00a0\u00a0 } \n\u00a0\u00a0\u00a0 and is blocked by the session at the start of the chain. \n<\/code><\/p><\/pre>\n
I would hope that a few things would be immediately obvious, particularly if it’s ‘your’ application that generated this issue <\/p>\n
1) The two sessions are running the following parts of the application.<\/p>\n
Session 1: Begin run_manager_pkg.finalize_all_values_prc(:v0); End; 
Session 2: ALTER INDEX “DOUG”.”VALUE_PK” REBUILD PARTITION “SYS_P4089”<\/p>\n
Which happened to fit in with what we were seeing. We have two concurrent runs which perform similar actions using different input files that load into different partitions.<\/p>\n
2) The first session is using Parallel Query (note the enq: PS – contention and different PX Deq wait events)<\/p>\n
3) The deadlock is a little unusual because it’s not between two transactions trying to lock database objects or rows being locked by the other session but between in-memory structures. One session is waiting on ‘row cache lock’ and the other is waiting on
\n‘library cache lock’, as opposed to waiting for specific row or
\ntable-level locks. This is also visible from the chain signature at the start of the trace file.<\/p>\n
Chain Signature: ‘library cache lock'<=’row cache lock’ (cycle) <\/p>\n
Armed with 2) and 3) in particular, my next step was to go to My Oracle Support, as usual. I find that Google isn’t too great with issues like this because some of them are quite specific and might not be affecting too many others. Sure enough, a search turned up :-<\/p>\n
Bug 14356507\u00a0 Deadlock between partition maintenance and parallel query operations
<\/strong>
Which is confirmed as affecting versions 11.2.0.2 and 11.2.0.3. The fix is in Bundle Patch 12 for Exadata, in Oracle 12.1 and is also available as one-off patch that we’re in the process of applying to different environments. <\/p>\n
The issue is that “When a parallel query is hard parsed, first QC hard parses the query and then all the slaves.\u00a0 When a partition maintenance operation (DDL) comes in between the hard parses of QC and Slaves.”, then you can hit the deadlock. There’s more detail in the bug notes, but it’s worth noting this phrase “This is basically a timing issue, in high concurrency environments.”, which means it only affects us very intermittently and is a nightmare to prove we’ve eliminated without a lot of testing.<\/p>\n
What I find a little disconcerting is that there seem to be quite a few of these library cache deadlock issues kicking around in recent versions that I haven’t been used to seeing in prior versions. Given some of the library cache madness I’ve seen in my few years with 11g, I do wonder what on earth they’ve done to it!<\/p>\n","protected":false},"excerpt":{"rendered":"
I’ve blogged about deadlocks in Oracle at least once before. I said then that although the following message in deadlock trace files is usually true, it isn’t always. The following deadlock is not an Oracle error. Deadlocks of\u00a0 this type can be expected if certain SQL statements are\u00a0\u00a0\u00a0\u00a0\u00a0 issued. The following information may aid in… Continue reading Not all Deadlocks are created the same<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"class_list":["post-1697","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1014,"url":"http:\/\/orcldoug.com\/blog\/2006\/07\/10\/being-open-minded\/","url_meta":{"origin":1697,"position":0},"title":"Being Open-minded","date":"July 10, 2006","format":false,"excerpt":"I think that one of the most important skills of a good DBA and one of the most difficult to maintain as your experience grows is to stay open-minded.When I got into work this morning, there was an email waiting for me from a frustrated developer who wanted to know\u2026","rel":"","context":"With 6 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1495,"url":"http:\/\/orcldoug.com\/blog\/2009\/05\/01\/diagnosing-locking-problems-using-ashlogminer-the-end\/","url_meta":{"origin":1697,"position":1},"title":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 The End","date":"May 1, 2009","format":false,"excerpt":"Except\u00a0it's not the\u00a0end, of course. What I mean is\u00a0that I usually agree with\u00a0what Miladin Modrakovic said in one of his comments on his first deadlock blog post.\"There is always way around.\"As I keep saying, there are many different ways of diagnosing locking problems. Which one works best\u00a0depends on the situation\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1016,"url":"http:\/\/orcldoug.com\/blog\/2006\/07\/12\/table-reorgs-and-statistics\/","url_meta":{"origin":1697,"position":2},"title":"Table reorgs and statistics","date":"July 12, 2006","format":false,"excerpt":"While working on the ITL deadlock problem (which looks like it's been fixed by the initrans increase and table rebuild), the developers highlighted another table as hitting this problem in the past. When I investigated, I found that initrans had already been set to 6 so this had obviously happened\u2026","rel":"","context":"With 10 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1283,"url":"http:\/\/orcldoug.com\/blog\/2007\/06\/10\/blogs-oracle-com-part-2\/","url_meta":{"origin":1697,"position":3},"title":"blogs.oracle.com … part 2","date":"June 10, 2007","format":false,"excerpt":"OK, I finally have a few technical things worth blogging about, so let me get this non-technical one wrapped up first. Here's part 1.The other part of Kevin's blog that was very relevant to my recent musings was the section titled 'Aristocracy or Meritocracy'. He talks about the close contact\u2026","rel":"","context":"With 7 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1542,"url":"http:\/\/orcldoug.com\/blog\/2009\/11\/15\/mos-survey\/","url_meta":{"origin":1697,"position":4},"title":"MOS Survey","date":"November 15, 2009","format":false,"excerpt":"I'm trying not to go on about the past weeks My Oracle Support fiasco, but surely this is Customer Relations 101 - someone senior apologises and at least gives the impression the company cares about their customers more than they do about making excuses and patting themselves on the back?Anyway,\u2026","rel":"","context":"With 1 comment","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1347,"url":"http:\/\/orcldoug.com\/blog\/2007\/11\/13\/the-money-shot\/","url_meta":{"origin":1697,"position":5},"title":"The Money Shot","date":"November 13, 2007","format":false,"excerpt":"I think that's what they call it in the press.I tend to be on the receiving end of humorous flak at my current site about my Oracle ACE status, including jokes about people stroking the fleece and the like. It's just the Scottish sense of humour, I suppose \ud83d\ude09 Anyway,\u2026","rel":"","context":"With 23 comments","img":{"alt_text":"","src":"\/serendipity\/uploads\/fleece.jpg","width":350,"height":200},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1697","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/comments?post=1697"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1697\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1697"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1697"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1697"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}