{"id":1492,"date":"2009-04-30T12:00:00","date_gmt":"2009-04-30T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1492"},"modified":"2009-04-30T12:00:00","modified_gmt":"2009-04-30T12:00:00","slug":"diagnosing-locking-problems-using-ashlogminer-part-9","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2009\/04\/30\/diagnosing-locking-problems-using-ashlogminer-part-9\/","title":{"rendered":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 9"},"content":{"rendered":"<p>This time, instead of dumping the contents of the log file for a specific Data Block Address (DBA), as in the last part, I\u2019m going to dump it for a specific operation type \u2013 Lock Rows (SELECT FOR UPDATE in this case) \u2013 which is part of the Row Operations layer (11) and is the LKR operation (4). This will allow me to eliminate less interesting activity and will include information for blocks other than the specific block that contains the PK_ID=313 row. <\/p>\n<p>\u00a0<\/p>\n<pre>SQL&gt; alter system dump logfile '&amp;&amp;my_member'\n\u00a0 2\u00a0 layer 11 opcode 4;\nold\u00a0\u00a0 1: alter system dump logfile '&amp;&amp;my_member'\nnew\u00a0\u00a0 1: alter system dump logfile '\/data\/oradata\/PPL\/redo03.log'<p><\/p><p>System altered.<\/p><\/pre>\n<p>\u00a0<\/p>\n<p>Next, a quick reminder of the transaction history from the previous tests, that this log file covers.<\/p>\n<p>Transaction ID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0Session 1 Activity\u00a0 Transaction ID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Session 2 Activity<\/p>\n<p>0003001100008615\u00a0 Whole Table Locked<br \/>\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 Locks Released<br \/>0002000100008DAA\u00a0 Two Rows Locked<br \/>\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\u00a0Locks Released<br \/>000900110000891B\u00a0 PK_ID=313 Locked\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 Waiting to lock PK_ID=313<br \/>\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 Lock Released\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 00080005000081D3\u00a0\u00a0\u00a0 PK_ID=313 Locked\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 <\/p>\n<p>Looking at the header (line numbers added by vi), I can see that the dump is restricted to Opcode 11.4.<\/p>\n<p>\u00a0<\/p>\n<pre>\u00a0\u00a0\u00a0 19\u00a0 DUMP OF REDO FROM FILE '\/data\/oradata\/PPL\/redo03.log'\n\u00a0\u00a0\u00a0 20\u00a0\u00a0 Opcode 11.4 only\n\u00a0\u00a0\u00a0 21\u00a0\u00a0 RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff\n\u00a0\u00a0\u00a0 22\u00a0\u00a0 SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff\n\u00a0\u00a0\u00a0 23\u00a0\u00a0 Times: creation thru eternity<\/pre>\n<p>\u00a0<\/p>\n<p>Next I search for \u2018xid: \u2018 to find the first transaction ID, which brings up the first redo record, all 2214 lines of it! Relax, I\u2019m not going to list it all here, just focus on the first CHANGE record.<\/p>\n<p>\u00a0<\/p>\n<pre>\u00a0\u00a0\u00a0 50\u00a0 REDO RECORD - Thread:1 RBA: 0x002304.00000002.0010 LEN: 0x45b0 VLD: 0x0d\n\u00a0\u00a0\u00a0 51\u00a0 SCN: 0x0000.050dc3e9 SUBSCN:\u00a0 1 04\/23\/2009 09:40:19\n\u00a0\u00a0\u00a0 52\u00a0 CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06125 OBJ:144543 SCN:0x0000.050dc005 SEQ:185 OP:11.4\n\u00a0\u00a0\u00a0 53\u00a0 KTB Redo\n\u00a0\u00a0\u00a0 54\u00a0 op: 0x01\u00a0 ver: 0x01\n\u00a0\u00a0\u00a0 55\u00a0 op: F\u00a0 xid:\u00a0 0x0003.011.00008615\u00a0\u00a0\u00a0 uba: 0x00803aaa.0f30.01\n\u00a0\u00a0\u00a0 56\u00a0 KDO Op code: LKR row dependencies Disabled\n\u00a0\u00a0\u00a0 57\u00a0\u00a0\u00a0 xtype: XA flags: 0x00000000\u00a0 bdba: 0x00c06125\u00a0 hdba: 0x00c06103\n\u00a0\u00a0\u00a0 58\u00a0 itli: 2\u00a0 ispac: 0\u00a0 maxfr: 4858\n\u00a0\u00a0\u00a0 59\u00a0 tabn: 0 slot: 183 to: 2<\/pre>\n<p>\u00a0<\/p>\n<p>I can see this is a change to a Data Block (Class 1), the Trancation ID is 0x0003.011.00008615 which matches the XID 0003001100008615 from V$TRANSACTION and that it\u2019s a row lock operation. Next up is a 5.2 operation that starts off the new transaction)<\/p>\n<p>\u00a0<\/p>\n<pre>\u00a0\u00a0\u00a0 60\u00a0 CHANGE #2 TYP:0 CLS:21 AFN:2 DBA:0x00800029 OBJ:4294967295 SCN:0x0000.050dc3c0 SEQ:\u00a0 1 OP:5.2\n\u00a0\u00a0\u00a0 61\u00a0 ktudh redo: slt: 0x0011 sqn: 0x00008615 flg: 0x000a siz: 108 fbi: 0\n\u00a0\u00a0\u00a0 62\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 uba: 0x00803aaa.0f30.01\u00a0\u00a0\u00a0 pxid:\u00a0 0x0000.000.00000000<\/pre>\n<p>\u00a0<\/p>\n<p>After that you\u2019ll see tons more 11.4 entries as the various locks are acquired. Next I\u2019ll search for the transaction ID for the second transaction (that locked two rows) by searching for \u2018xid:\u00a0 0x0002\u2019 (two spaces in that string).<\/p>\n<p>\u00a0<\/p>\n<pre>192358\u00a0 REDO RECORD - Thread:1 RBA: 0x002304.00000ce8.0010 LEN: 0x0238 VLD: 0x0d\n192359\u00a0 SCN: 0x0000.050dc41f SUBSCN:\u00a0 1 04\/23\/2009 09:40:20\n192360\u00a0 CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc411 SEQ:102 OP:11.4\n192361\u00a0 KTB Redo\n192362\u00a0 op: 0x01\u00a0 ver: 0x01\n192363\u00a0 op: F\u00a0 xid:\u00a0 0x0002.001.00008daa\u00a0\u00a0\u00a0 uba: 0x00808827.124c.31\n192364\u00a0 KDO Op code: LKR row dependencies Disabled\n192365\u00a0\u00a0\u00a0 xtype: XA flags: 0x00000000\u00a0 bdba: 0x00c06104\u00a0 hdba: 0x00c06103\n192366\u00a0 itli: 3\u00a0 ispac: 0\u00a0 maxfr: 4858\n192367\u00a0 tabn: 0 slot: 2 to: 3<\/pre>\n<p>\u00a0<\/p>\n<p>Looking at the line numbers, you can probably see why I didn\u2019t want to show you all of the REDO RECORDs for the first transaction! Checking the transaction ID, that\u2019s the one we\u2019re looking for. While I\u2019m at it, I might as well track down the last two transactions by searching for their xid: <\/p>\n<p>\u00a0<\/p>\n<pre>192447\u00a0 REDO RECORD - Thread:1 RBA: 0x002304.00000cea.0010 LEN: 0x0180 VLD: 0x0d\n192448\u00a0 SCN: 0x0000.050dc423 SUBSCN:\u00a0 1 04\/23\/2009 09:40:25\n192449\u00a0 CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc41f SEQ:\u00a0 4 OP:11.4\n192450\u00a0 KTB Redo\n192451\u00a0 op: 0x01\u00a0 ver: 0x01\n192452\u00a0 op: F\u00a0 xid:\u00a0 0x0009.011.0000891b\u00a0\u00a0\u00a0 uba: 0x0081e118.14ee.05\n192453\u00a0 KDO Op code: LKR row dependencies Disabled\n192454\u00a0\u00a0\u00a0 xtype: XA flags: 0x00000000\u00a0 bdba: 0x00c06104\u00a0 hdba: 0x00c06103\n192455\u00a0 itli: 3\u00a0 ispac: 0\u00a0 maxfr: 4858\n192456\u00a0 tabn: 0 slot: 3 to: 3<p><\/p><p>192496\u00a0 REDO RECORD - Thread:1 RBA: 0x002304.00000cec.0010 LEN: 0x0180 VLD: 0x0d\n192497\u00a0 SCN: 0x0000.050dc428 SUBSCN:\u00a0 1 04\/23\/2009 09:40:34\n192498\u00a0 CHANGE #1 TYP:0 CLS: 1 AFN:3 DBA:0x00c06104 OBJ:144543 SCN:0x0000.050dc426 SEQ:\u00a0 1 OP:11.4\n192499\u00a0 KTB Redo\n192500\u00a0 op: 0x01\u00a0 ver: 0x01\n192501\u00a0 op: F\u00a0 xid:\u00a0 0x0008.005.000081d3\u00a0\u00a0\u00a0 uba: 0x0081eda9.1058.20\n192502\u00a0 KDO Op code: LKR row dependencies Disabled\n192503\u00a0\u00a0\u00a0 xtype: XA flags: 0x00000000\u00a0 bdba: 0x00c06104\u00a0 hdba: 0x00c06103\n192504\u00a0 itli: 3\u00a0 ispac: 0\u00a0 maxfr: 4858\n192505\u00a0 tabn: 0 slot: 3 to: 3<\/p><\/pre>\n<p>Yep, they both look right (which is more than can be said for Log Miner\u2019s output!). The fact is that you could probably work out which transaction had locked the rows and the type of work it was doing, but still no nearer finding the offending SQL statement, really.<\/p>\n<p>In the next and absolutely definitely last part, I&#8217;ll have a brief overview of some other suggestions such as <a href=\"http:\/\/oraclue.com\/2009\/04\/23\/detecting-deadlock-source-part-2\/\">Miladin Modrakivic&#8217;s<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>This time, instead of dumping the contents of the log file for a specific Data Block Address (DBA), as in the last part, I\u2019m going to dump it for a specific operation type \u2013 Lock Rows (SELECT FOR UPDATE in this case) \u2013 which is part of the Row Operations layer (11) and is the&hellip; <a class=\"more-link\" href=\"http:\/\/orcldoug.com\/blog\/2009\/04\/30\/diagnosing-locking-problems-using-ashlogminer-part-9\/\">Continue reading <span class=\"screen-reader-text\">Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 9<\/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-1492","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1488,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/22\/diagnosing-locking-problems-using-ashlogminer-part-7\/","url_meta":{"origin":1492,"position":0},"title":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 7","date":"April 22, 2009","format":false,"excerpt":"Picking up from the end of the last example, I immediately generated a log file dump as follows. (You'll need to look back at Part 5 to see that the ROWID, log file name etc. match up or just trust me that these steps came from a continuation of the\u2026","rel":"","context":"With 2 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1484,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/17\/diagnosing-locking-problems-using-ash-part-5\/","url_meta":{"origin":1492,"position":1},"title":"Diagnosing Locking Problems using ASH \u2013 Part 5","date":"April 17, 2009","format":false,"excerpt":"... and so it continues.Coincidentally, the subject of tracking down locking problems after they occurred cropped up on the Oak Table mailing list just after the last post. Several suggestions were offered but I think the nearest and most detailed suggestion was that proposed by Kyle Hailey, ex-Oracle and now\u2026","rel":"","context":"With 5 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":941,"url":"http:\/\/orcldoug.com\/blog\/2005\/09\/01\/nice-sqlldr-option-for-external-tables\/","url_meta":{"origin":1492,"position":2},"title":"Nice SQLLDR option for external tables","date":"September 1, 2005","format":false,"excerpt":"(Trying this one again to see if it appears on Orablogs)SQLLDR has the following command line option EXTERNAL_TABLE = GENERATE_ONLY which, when you give it an old-fashioned SQLLDR control file, will spit out the External Table equivalent in the log file.e.g.Control FileLOAD DATAINFILE 'test.txt'TRUNCATEINTO TABLE doug_testFIELDS TERMINATED BY \"\"(pk,test_value CHAR\u2026","rel":"","context":"With 1 comment","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1697,"url":"http:\/\/orcldoug.com\/blog\/2013\/03\/11\/not-all-deadlocks-are-created-the-same\/","url_meta":{"origin":1492,"position":3},"title":"Not all Deadlocks are created the same","date":"March 11, 2013","format":false,"excerpt":"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\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1645,"url":"http:\/\/orcldoug.com\/blog\/2011\/07\/24\/systemstate-dump-warning\/","url_meta":{"origin":1492,"position":4},"title":"Systemstate Dump warning","date":"July 24, 2011","format":false,"excerpt":"Whilst investigating the latest of our many library cache contention problems on 11.2, I made the fatal mistake of relying on my previous experience combined with a standard Oracle Support note describing how to diagnose such problems. When the system was apparently hung (although the reality was that one session\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1403,"url":"http:\/\/orcldoug.com\/blog\/2008\/04\/17\/moving-awr-data\/","url_meta":{"origin":1492,"position":5},"title":"Moving AWR data","date":"April 17, 2008","format":false,"excerpt":"Note - features in this post require the Diagnostics Pack license[I originally had the first section at the end of the blog post, but then realised I might as well get the bad news out of the way to save you wasting your time if you're not interested]A small section\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1492","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=1492"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1492\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1492"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1492"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1492"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}