{"id":1488,"date":"2009-04-22T12:00:00","date_gmt":"2009-04-22T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1488"},"modified":"2009-04-22T12:00:00","modified_gmt":"2009-04-22T12:00:00","slug":"diagnosing-locking-problems-using-ashlogminer-part-7","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2009\/04\/22\/diagnosing-locking-problems-using-ashlogminer-part-7\/","title":{"rendered":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 7"},"content":{"rendered":"

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<\/a> to see that the ROWID, log file name etc. match up or just trust me that these steps came from a continuation of the same SYS session used in that test.)<\/p>\n

First I’m going to work out the file and block number for the block containing the locked row in the test. That’s why I selected the ROWID before I locked it.<\/p>\n

SYS@TEST1020> select file_id, file_name, dbms_rowid.rowid_block_number('&&my_rowid')\n\u00a0 2\u00a0 from dba_data_files\n\u00a0 3\u00a0 where file_id = dbms_rowid.rowid_to_absolute_fno('&&my_rowid','TESTUSER','TEST_TAB1');\nEnter value for my_rowid: AAAN2NAAKAAAaBLAEX\nold\u00a0\u00a0 1: select file_id, file_name, dbms_rowid.rowid_block_number('&&my_rowid')\nnew\u00a0\u00a0 1: select file_id, file_name, dbms_rowid.rowid_block_number('AAAN2NAAKAAAaBLAEX')\nold\u00a0\u00a0 3: where file_id = dbms_rowid.rowid_to_absolute_fno('&&my_rowid', 'TESTUSER', \n               'TEST_TAB1')\nnew\u00a0\u00a0 3: where file_id = dbms_rowid.rowid_to_absolute_fno('AAAN2NAAKAAAaBLAEX','TESTUSER', \n               'TEST_TAB1')\n\n\u00a0\u00a0 FILE_ID\n----------\nFILE_NAME\n---------------------------------------------------\nDBMS_ROWID.ROWID_BLOCK_NUMBER('AAAN2NAAKAAAABLAEX')\n---------------------------------------------------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 10\nC:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\TEST_DATA01.DBF\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 106571<\/pre>\n
Now that I have a file and block number, I’ll dump the redo log file but restrict the dump to entries related to that block.<\/p>\n
SYS@TEST1020> alter session set max_dump_file_size=unlimited;\n\nSession altered.\n\nSYS@TEST1020> alter system dump logfile '&&my_member'\n\u00a0 2\u00a0\u00a0\u00a0\u00a0 dba min 10 106571 dba max 10 106571<\/strong>;\nold\u00a0\u00a0 1: alter system dump logfile '&&my_member'\nnew\u00a0\u00a0 1: alter system dump logfile 'C:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\REDO01.LOG'\n\nSystem altered.<\/pre>\n
The trace file is created in user_dump_dest and I’ve uploaded it here<\/a>. Near the start of the file, I can check that block range.<\/p>\n
DUMP OF REDO FROM FILE 'C:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\REDO01.LOG'\n\u00a0Opcodes *.*\n\u00a0DBAs: (file # 10, block # 106571) thru (file # 10, block # 106571)<\/strong>\n\u00a0RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff\n\u00a0SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff<\/pre>\n
The first redo entry appears soon after<\/p>\n
REDO RECORD - Thread:1 RBA: 0x0000b3.00000009.0010 LEN: 0x0210 VLD: 0x0d\nSCN: 0x0000.008a42e6 SUBSCN:\u00a0 1 04\/20\/2009 20:46:57\nCHANGE #1 TYP:2 CLS: 1<\/strong> AFN:10 DBA:0x0281a04b<\/strong> OBJ:56717<\/strong> SCN:0x0000.008a4239 SEQ:\u00a0 2 OP:11.19<\/strong>\nKTB Redo \nop: 0x11\u00a0 ver: 0x01\u00a0 \nop: F\u00a0 xid:\u00a0 0x000a.024.00001864<\/strong>\u00a0\u00a0\u00a0 uba: 0x0080009d.031a.27<\/pre>\n
CLS: 1 – Data Class Block
OP:11.19 – Operation Update Multiple Rows.<\/p>\n
Verify OBJ:56717 is TEST_TAB1 –<\/p>\n
TESTUSER@TEST1020> select object_name, object_type\n\u00a0 2\u00a0 from user_objects\n\u00a0 3\u00a0 where object_id=56717;\n\nOBJECT_NAME\n-------------------\nOBJECT_TYPE\n-------------------\nTEST_TAB1\nTABLE<\/pre>\n
Verify DBA: <\/p>\n
SYS@TEST1020> select to_char(dbms_utility.make_data_block_address(10,106571),\n\u00a0 2\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 'XXXXXXXX') from dual;\n\nTO_CHAR(D\n---------\n\u00a0 281A04B<\/pre>\n
Transaction ID 0x000a.024.00001864 matches XID 0A00240064180000 from V$TRANSACTION during the test, albeit in the rearranged format.<\/p>\n
So this is definitely the blocking transaction and I can see the new value for the OBJECT_NAME column below …<\/p>\n
col\u00a0 1: [ 9]\u00a0 53 45 53 53 49 4f 4e 20 31<\/pre>\n
Which is the hexadecimal version of the ASCII string ”SESSION 1′. Further on still, we’ll see it being updated to ‘SESSION 2’.<\/p>\n
I could wade through that dump all day (and it might be a subject for future posts) but a couple of things should be clear. <\/p>\n
1) The redo log file contains plenty of information about the row updates, so if Log Miner is returning a single COMMIT action, either it’s not working properly or I’m doing something wrong.<\/p>\n
2) The contents of the redo log file might be an indicator<\/em> of the SQL statement that caused the blocking problem, but it won’t tell me what that statement was.<\/p>\n
At this stage, I would say that ASH is starting to look more effective (in those cases where it can be used) than the alternatives being proposed. Remember, the whole point with ASH is that I don’t need to predict when these problems might occur, so any solution that needs me to switch on traces is limited.<\/p>\n
If you’re interested in learning more about log file dumps, I recommend you read Riyaj Shamsudeen’s Redo Internals paper<\/a> and Julian Dyke’s Redo Internals presentation<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":"
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 same SYS session used in… Continue reading Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 7<\/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-1488","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1484,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/17\/diagnosing-locking-problems-using-ash-part-5\/","url_meta":{"origin":1488,"position":0},"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":1017,"url":"http:\/\/orcldoug.com\/blog\/2006\/07\/13\/alter-table-move-and-table-stats\/","url_meta":{"origin":1488,"position":1},"title":"alter table … move and table stats","date":"July 13, 2006","format":false,"excerpt":"Howard Rogers left a comment on my last blog, showing an example of using alter table ... move on a 10gR2 database on Linux. In his example, unlike mine, the table rebuild did not nullify the table's statistics. I admit I was surprised myself when I ran my example yesterday\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1478,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-2\/","url_meta":{"origin":1488,"position":2},"title":"Diagnosing Locking Problems using ASH – Part 2","date":"March 30, 2009","format":false,"excerpt":"Some features in this post require a Diagnostics Pack license.I tried the graphical approach to tracking down the root cause of a locking problem in the last part. Now let's look at the underlying ASH data. I ran the same test after bouncing my test instance to start from a\u2026","rel":"","context":"With 3 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1491,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/23\/diagnosing-locking-problems-using-ashlogminer-part-8\/","url_meta":{"origin":1488,"position":3},"title":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 Part 8","date":"April 23, 2009","format":false,"excerpt":"So what about those SELECT FOR UPDATEs?I know that they\u2019ll generate redo entries and so something should appear in both log file dumps and the LogMiner output, but what exactly will appear? (This is all on Oracle 10.2.0.4)For this post I\u2019ll go back to the example from Part 4, where\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":1488,"position":4},"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":[]},{"id":1480,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/31\/diagnosing-locking-problems-using-ash-part-3\/","url_meta":{"origin":1488,"position":5},"title":"Diagnosing Locking Problems using ASH – Part 3","date":"March 31, 2009","format":false,"excerpt":"Some features in this post require a Diagnostics Pack license.In the last part I described a locking scenario where the blocking session had only executed one SQL statement that was quick enough to avoid being sampled by ASH and is now inactive. As a result, there is no ASH data\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1488","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=1488"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1488\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1488"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1488"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1488"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}