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

… and so it continues.<\/p>\n

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<\/a>, ex-Oracle and now working Embarcadero. There were one or two problems with the original email which I’ve fixed up here …<\/p>\n

For the wait event class I was teaching I wanted to show an example of taking ASH data and finding the blocking statement in the log miner data, but found this was less than reliable. Sometimes it would work sometimes it didn’t. Not sure what the issue was. I think dumping the redo log itself would be more dependable. I think logminer might not report everything – ie I think there is some filtering going on.<\/p>\n

Anyway here are some steps that might be of use to people. I get\u00a0 XID but you probably don’t need it, but I recall the XID being useful in doing the redo log dumps<\/em>

Setup<\/strong><\/u><\/p>\n

SYS@TEST1020> set lines 120\nSYS@TEST1020> column member format a60\nSYS@TEST1020>\nSYS@TEST1020> alter system switch logfile;\n\nSystem altered.\n\nSYS@TEST1020> select group#, thread#, status from v$log;\n\n    GROUP#    THREAD# STATUS\n---------- ---------- ----------------\n         1          1 CURRENT\n         2          1 ACTIVE\n         3          1 ACTIVE\n\nSYS@TEST1020> select group#, member from v$logfile;\n\n    GROUP# MEMBER\n---------- ------------------------------------------------------------\n         1 C:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\REDO01.LOG\n         2 C:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\REDO02.LOG\n         3 C:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\REDO03.LOG\n\nSYS@TEST1020> exec dbms_logmnr.add_logfile('&&my_member');\nEnter value for my_member: C:\\ORACLE\\PRODUCT\\10.2.0\\ORADATA\\TEST1020\\REDO01.LOG\n\nPL\/SQL procedure successfully completed.\n\nSYS@TEST1020> exec dbms_logmnr.start_logmnr(options => dbms_logmnr.dict_from_online_catalog);\n\nPL\/SQL procedure successfully completed.<\/pre>\n

Test Case<\/strong><\/u><\/p>\n
Session 1<\/p>\n
TESTUSER@TEST1020> create table test_tab1\n                      as select object_id pk_id, object_name from all_objects;\n\nTable created.\n\nTESTUSER@TEST1020> select rowid, object_name from test_tab1 where pk_id=313;\n\nROWID              OBJECT_NAME\n------------------ ------------------------------\nAAAN2NAAKAAAaBLAEX SYSTEM_PRIVILEGE_MAP\n\nTESTUSER@TEST1020> update test_tab1 set object_name='SESSION 1' where pk_id=313;\n\n1 row updated.<\/pre>\n
Session 2<\/p>\n
TESTUSER@TEST1020> update test_tab1 set object_name='SESSION 2' where pk_id=313;<\/pre>\n
So Session 1 is now blocking session 2 … have a look in V$TRANSACTION<\/p>\n
SYS@TEST1020> select start_time, xid, xidusn, xidslot, xidsqn, start_scn, \n              to_char(start_scn, 'XXXXXXXXXX') \n              from v$transaction order by start_time;\n\nSTART_TIME           XID                  XIDUSN    XIDSLOT     XIDSQN  START_SCN TO_CHAR(STA\n-------------------- ---------------- ---------- ---------- ---------- ---------- -----------\n04\/20\/09 20:46:39    0A00240064180000         10         36       6244          0           0<\/pre>\n
Commit Session 1<\/p>\n
TESTUSER@TEST1020> commit;\n\nCommit complete.<\/pre>\n
… so that Session 2 is released.<\/p>\n
\n1 row updated.<\/pre>\n
and take a look in V$TRANSACTION at the new transaction details<\/p>\n
SYS@TEST1020> select start_time, xid, xidusn, xidslot, xidsqn, start_scn, to_cha\nr(start_scn, 'XXXXXXXXXX') from v$transaction order by start_time;\n\nSTART_TIME           XID                  XIDUSN    XIDSLOT     XIDSQN  START_SCN TO_CHAR(STA\n-------------------- ---------------- ---------- ---------- ---------- ---------- -----------\n04\/20\/09 20:46:54    08002000681F0000          8         32       8040    9061094      8A42E6<\/pre>\n
\nSo the blocking lock problem has now cleared. Let’s start gathering information to see if we can identify the problem.<\/p>\n
Analysis<\/strong><\/u><\/p>\n
Parameters for ‘enq: TX – Row Lock Contention’
\u00a0\u00a0\u00a0 P2=usn<<16||slot
\u00a0\u00a0\u00a0 P3=Sequence
\u00a0\u00a0\u00a0\u00a0 =>\u00a0 XID<\/p>\n
Let’s find our WAITER and the BLOCKING XID<\/p>\n
SYS@TEST1020> select * from\n  2     (select lpad(ltrim(to_char(p2,'XXXXXX')),6,'0')||\n  3             '00'||\n  4             ltrim(to_char(mod(p3,256),'XX'))||\n  5             ltrim(to_char(trunc(p3\/256),'XX'))||\n  6             '0000' block_xid,\n  7             to_char(p2,'XXXXXXXX') p2hex,\n  8             to_char(p3,'XXXXXXXX') p3hex,\n  9             trunc(p2\/65536) usn,\n 10             mod(p2,65536) slot,\n 11             p3 sqn, xid wait_xid\n 12     from v$active_session_history\n 13     where event like 'enq: T%'\n 14     order by sample_time desc) where rownum < 2;\n\nBLOCK_XID          P2HEX     P3HEX            USN       SLOT        SQN WAIT_XID\n\n------------------ --------- --------- ---------- ---------- ---------- --------\n0A00240064180000       A0024      1864         10         36       6244<\/pre>\n
Now let’s use logminer to find out what the BLOCKING SQL was<\/p>\n
SYS@TEST1020> select username, session# sid, serial# , sql_redo from v$logmnr_co\nntents where  XID = '&&blocking_xid'\n  2  \/\nEnter value for blocking_xid: 0A00240064180000\nold   1: select username, session# sid, serial# , sql_redo from v$logmnr_content\ns where  XID = '&&blocking_xid'\nnew   1: select username, session# sid, serial# , sql_redo from v$logmnr_content\ns where  XID = '0A00240064180000'\n\nUSERNAME                              SID    SERIAL#\n------------------------------ ---------- ----------\nSQL_REDO\n--------------------------------------------------------------------------------\nUNKNOWN                                 0          0\ncommit;<\/pre>\n
Oh 🙁<\/p>\n
Well, how about trying a different approach?<\/p>\n
SYS@TEST1020> select distinct xid , xidusn, xidslt, xidsqn, username, session# s\nid, serial# , sql_redo\n  2  from v$logmnr_contents\n  3  where timestamp > sysdate- &minutes\/(60*24)\n  4  and xidusn=10\n  5  and xidslt=36;\nEnter value for minutes: 10\nold   3: where timestamp > sysdate- &minutes\/(60*24)\nnew   3: where timestamp > sysdate- 10\/(60*24)\n\nXID                  XIDUSN     XIDSLT     XIDSQN USERNAME\n        SID    SERIAL#\n---------------- ---------- ---------- ---------- ------------------------------\n ---------- ----------\nSQL_REDO\n--------------------------------------------------------------------------------\n----------------------------------------\n0A00240064180000         10         36       6244 UNKNOWN\n          0          0\ncommit;<\/pre>\n
Which isn’t too helpful – I can’t see any information about Session 1’s row update. If anyone has any ideas why, I’m all ears.<\/p>\n
In the next post I’ll look at a redo log file dump to see if that has any more information.<\/p>\n","protected":false},"excerpt":{"rendered":"
… 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 working Embarcadero. There were… Continue reading Diagnosing Locking Problems using ASH \u2013 Part 5<\/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-1484","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1487,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/20\/diagnosing-locking-problems-using-ash-part-6\/","url_meta":{"origin":1484,"position":0},"title":"Diagnosing Locking Problems using ASH \u2013 Part 6","date":"April 20, 2009","format":false,"excerpt":"\"Toto, I've a feeling we're not in Kansas any more.\"What started as a simple write-up of a course demo gone wrong (or right, depending the way you look at these things) has grown arms and legs and staggered away from the original intention to talk about ASH. so I thought\u2026","rel":"","context":"With 1 comment","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1488,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/22\/diagnosing-locking-problems-using-ashlogminer-part-7\/","url_meta":{"origin":1484,"position":1},"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":1477,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-1\/","url_meta":{"origin":1484,"position":2},"title":"Diagnosing Locking Problems using ASH – Part 1","date":"March 30, 2009","format":false,"excerpt":"Some features in this post require a Diagnostics Pack license.There are few better illustrations of the utility of ASH data than the ability to detect and diagnose locking problems*, even after they've occurred. Because ASH is sampling all active sessions all of the time, you should have information both for\u2026","rel":"","context":"Similar post","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":1484,"position":3},"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":[]},{"id":1478,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-2\/","url_meta":{"origin":1484,"position":4},"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":1489,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/22\/how-to-induce-log-file-sync-waits\/","url_meta":{"origin":1484,"position":5},"title":"How to induce log file sync waits","date":"April 22, 2009","format":false,"excerpt":"(With my tongue causing a minor gash on the inside of my cheek ....)I'm working on an application that seems to suffer constant long waits on log file parallel write and, consequently, log file sync. I thought that the 54 ms log file parallel writes where just typical of an\u2026","rel":"","context":"With 2 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1484","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=1484"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1484\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1484"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1484"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1484"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}