Entries tagged as ash
Apr 20: Diagnosing Locking Problems using ASH – Part 6
"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 it might be worth taking a breather and see where we’ve been so far, before pressing on with another couple of posts.
Part 1 – Introduced a blocking lock problem and showed how it would look in the OEM DB/Grid Control GUI.
Part 2 – Demonstrated that you might not see any ASH samples for the blocking session if it doesn’t generate enough activity to be captured.
Part 3 – Demonstrated that even if the blocking session *has* been active enough to be sampled, you might not have the specific activity that caused the problem.
Part 4 – Reinforced part 3 to show that you might *think* you’re looking at the SQL statement which was holding the blocking lock when you actually aren’t and highlighted JB’s point that there is no way of knowing the SQL statement that was holding a particular lock. I see that Jonathan Lewis has posted an illustration of this although let’s wait to see if Tanel Poder comes up with something
I decided at this point to draw some conclusions as to the limitations of ASH as a tool in diagnosing locking problems after they’ve cleared. In amongst the meandering detail, it's important to reiterate that objective. There are lots of ways of diagnosing locking problems that are happening right now or that you expect to happen in future.
Part 5 – The same subject cropped up on the Oak Table list and in amongst the suggestions were a couple to use LogMiner. One was from Kyle Hailey and I posted his scripts and output verbatim, but there were a few cut and paste errors and so I was faffing around with the post for a while and eventually added a comment to say I’d fix it later. I’ve now done so, re-running the tests with the correct code and removed the comment from the post. Sadly, none of the corrections fixed the two central problems with this approach
a) Kyle and I have both found LogMiner behaviour to be very flaky indeed and it doesn’t seem to return the results I’d expect, over multiple tests by two different ‘testers’. (See the last post for an example.)
b) I had to change the examples to use UPDATE statements rather than SELECT FOR UPDATEs.
I’ll be looking at these two issues in Parts 7 and 8 (I think) but who knows what turn these posts will take next! Here’s where I think I might be heading
Part 6 – You’re reading it.
Part 7 – Redo log dump confirmation that the LogMiner queries in Part 5 aren't showing what I'd expect.
Part 8 – Redo log dump confirmation that redo entries won’t help with the original SELECT FOR UPDATE example anyway.
Part 9 – Can I stop now, or should I attempt to reach a double-digit part number for the first (and hopefully last) time?
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 it might be worth taking a breather and see where we’ve been so far, before pressing on with another couple of posts.
Part 1 – Introduced a blocking lock problem and showed how it would look in the OEM DB/Grid Control GUI.
Part 2 – Demonstrated that you might not see any ASH samples for the blocking session if it doesn’t generate enough activity to be captured.
Part 3 – Demonstrated that even if the blocking session *has* been active enough to be sampled, you might not have the specific activity that caused the problem.
Part 4 – Reinforced part 3 to show that you might *think* you’re looking at the SQL statement which was holding the blocking lock when you actually aren’t and highlighted JB’s point that there is no way of knowing the SQL statement that was holding a particular lock. I see that Jonathan Lewis has posted an illustration of this although let’s wait to see if Tanel Poder comes up with something
I decided at this point to draw some conclusions as to the limitations of ASH as a tool in diagnosing locking problems after they’ve cleared. In amongst the meandering detail, it's important to reiterate that objective. There are lots of ways of diagnosing locking problems that are happening right now or that you expect to happen in future.
Part 5 – The same subject cropped up on the Oak Table list and in amongst the suggestions were a couple to use LogMiner. One was from Kyle Hailey and I posted his scripts and output verbatim, but there were a few cut and paste errors and so I was faffing around with the post for a while and eventually added a comment to say I’d fix it later. I’ve now done so, re-running the tests with the correct code and removed the comment from the post. Sadly, none of the corrections fixed the two central problems with this approach
a) Kyle and I have both found LogMiner behaviour to be very flaky indeed and it doesn’t seem to return the results I’d expect, over multiple tests by two different ‘testers’. (See the last post for an example.)
b) I had to change the examples to use UPDATE statements rather than SELECT FOR UPDATEs.
I’ll be looking at these two issues in Parts 7 and 8 (I think) but who knows what turn these posts will take next! Here’s where I think I might be heading
Part 6 – You’re reading it.
Part 7 – Redo log dump confirmation that the LogMiner queries in Part 5 aren't showing what I'd expect.
Part 8 – Redo log dump confirmation that redo entries won’t help with the original SELECT FOR UPDATE example anyway.
Part 9 – Can I stop now, or should I attempt to reach a double-digit part number for the first (and hopefully last) time?
Apr 17: Diagnosing Locking Problems using ASH – Part 5
... 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 one or two problems with the original email which I've fixed up here ...
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.
Anyway here are some steps that might be of use to people. I get XID but you probably don't need it, but I recall the XID being useful in doing the redo log dumps
Setup
Test Case
Session 1
Session 2
So Session 1 is now blocking session 2 ... have a look in V$TRANSACTION
Commit Session 1
... so that Session 2 is released.
and take a look in V$TRANSACTION at the new transaction details
So the blocking lock problem has now cleared. Let's start gathering information to see if we can identify the problem.
Analysis
Parameters for 'enq: TX - Row Lock Contention'
P2=usn<<16||slot
P3=Sequence
=> XID
Let's find our WAITER and the BLOCKING XID
Now let's use logminer to find out what the BLOCKING SQL was
Oh
Well, how about trying a different approach?
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.
In the next post I'll look at a redo log file dump to see if that has any more information.
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 one or two problems with the original email which I've fixed up here ...
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.
Anyway here are some steps that might be of use to people. I get XID but you probably don't need it, but I recall the XID being useful in doing the redo log dumps
Setup
SYS@TEST1020> set lines 120
SYS@TEST1020> column member format a60
SYS@TEST1020>
SYS@TEST1020> alter system switch logfile;
System altered.
SYS@TEST1020> select group#, thread#, status from v$log;
GROUP# THREAD# STATUS
---------- ---------- ----------------
1 1 CURRENT
2 1 ACTIVE
3 1 ACTIVE
SYS@TEST1020> select group#, member from v$logfile;
GROUP# MEMBER
---------- ------------------------------------------------------------
1 C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO01.LOG
2 C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO02.LOG
3 C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO03.LOG
SYS@TEST1020> exec dbms_logmnr.add_logfile('&&my_member');
Enter value for my_member: C:\ORACLE\PRODUCT\10.2.0\ORADATA\TEST1020\REDO01.LOG
PL/SQL procedure successfully completed.
SYS@TEST1020> exec dbms_logmnr.start_logmnr(options => dbms_logmnr.dict_from_online_catalog);
PL/SQL procedure successfully completed.Test Case
Session 1
TESTUSER@TEST1020> create table test_tab1
as select object_id pk_id, object_name from all_objects;
Table created.
TESTUSER@TEST1020> select rowid, object_name from test_tab1 where pk_id=313;
ROWID OBJECT_NAME
------------------ ------------------------------
AAAN2NAAKAAAaBLAEX SYSTEM_PRIVILEGE_MAP
TESTUSER@TEST1020> update test_tab1 set object_name='SESSION 1' where pk_id=313;
1 row updated.Session 2
TESTUSER@TEST1020> update test_tab1 set object_name='SESSION 2' where pk_id=313;
So Session 1 is now blocking session 2 ... have a look in V$TRANSACTION
SYS@TEST1020> select start_time, xid, xidusn, xidslot, xidsqn, start_scn,
to_char(start_scn, 'XXXXXXXXXX')
from v$transaction order by start_time;
START_TIME XID XIDUSN XIDSLOT XIDSQN START_SCN TO_CHAR(STA
-------------------- ---------------- ---------- ---------- ---------- ---------- -----------
04/20/09 20:46:39 0A00240064180000 10 36 6244 0 0Commit Session 1
TESTUSER@TEST1020> commit; Commit complete.
... so that Session 2 is released.
1 row updated.
and take a look in V$TRANSACTION at the new transaction details
SYS@TEST1020> select start_time, xid, xidusn, xidslot, xidsqn, start_scn, to_cha r(start_scn, 'XXXXXXXXXX') from v$transaction order by start_time; START_TIME XID XIDUSN XIDSLOT XIDSQN START_SCN TO_CHAR(STA -------------------- ---------------- ---------- ---------- ---------- ---------- ----------- 04/20/09 20:46:54 08002000681F0000 8 32 8040 9061094 8A42E6
So the blocking lock problem has now cleared. Let's start gathering information to see if we can identify the problem.
Analysis
Parameters for 'enq: TX - Row Lock Contention'
P2=usn<<16||slot
P3=Sequence
=> XID
Let's find our WAITER and the BLOCKING XID
SYS@TEST1020> select * from 2 (select lpad(ltrim(to_char(p2,'XXXXXX')),6,'0')|| 3 '00'|| 4 ltrim(to_char(mod(p3,256),'XX'))|| 5 ltrim(to_char(trunc(p3/256),'XX'))|| 6 '0000' block_xid, 7 to_char(p2,'XXXXXXXX') p2hex, 8 to_char(p3,'XXXXXXXX') p3hex, 9 trunc(p2/65536) usn, 10 mod(p2,65536) slot, 11 p3 sqn, xid wait_xid 12 from v$active_session_history 13 where event like 'enq: T%' 14 order by sample_time desc) where rownum < 2; BLOCK_XID P2HEX P3HEX USN SLOT SQN WAIT_XID ------------------ --------- --------- ---------- ---------- ---------- -------- 0A00240064180000 A0024 1864 10 36 6244
Now let's use logminer to find out what the BLOCKING SQL was
SYS@TEST1020> select username, session# sid, serial# , sql_redo from v$logmnr_co ntents where XID = '&&blocking_xid' 2 / Enter value for blocking_xid: 0A00240064180000 old 1: select username, session# sid, serial# , sql_redo from v$logmnr_content s where XID = '&&blocking_xid' new 1: select username, session# sid, serial# , sql_redo from v$logmnr_content s where XID = '0A00240064180000' USERNAME SID SERIAL# ------------------------------ ---------- ---------- SQL_REDO -------------------------------------------------------------------------------- UNKNOWN 0 0 commit;
Oh
Well, how about trying a different approach?
SYS@TEST1020> select distinct xid , xidusn, xidslt, xidsqn, username, session# s
id, serial# , sql_redo
2 from v$logmnr_contents
3 where timestamp > sysdate- &minutes/(60*24)
4 and xidusn=10
5 and xidslt=36;
Enter value for minutes: 10
old 3: where timestamp > sysdate- &minutes/(60*24)
new 3: where timestamp > sysdate- 10/(60*24)
XID XIDUSN XIDSLT XIDSQN USERNAME
SID SERIAL#
---------------- ---------- ---------- ---------- ------------------------------
---------- ----------
SQL_REDO
--------------------------------------------------------------------------------
----------------------------------------
0A00240064180000 10 36 6244 UNKNOWN
0 0
commit;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.
In the next post I'll look at a redo log file dump to see if that has any more information.
Comments