Apr 9: Diagnosing Locking Problems using ASH – Part 4
Some features in this post require a Diagnostics Pack license.
No sooner had I finished part 3 with some conclusions than I thought of another example I should have included and then someone else made a comment in an email which suggested another. (Thanks, JB!)
I’ll try to deal with that point and some other thoughts I had here in a further example. For this example, I decided to suggest how to create a quick table so that you can test this out for yourself.
As easy as that.
In the last part I showed that the SQL_ID for the last sample of a blocking session immediately before it went idle might not be the SQL statement holding the lock. In that case, it was fairly obvious that it wasn’t because it was a simple query that couldn’t have been responsible. However, it’s likely to be even more confusing if the SQL_ID captured by the ASH sample *looks* like it’s responsible, but isn’t, and the previous example didn't illustrate that clearly.
Session 1 – Connected as TESTUSER
So session 1 has executed three different queries, all of which lock one or more rows including the row with PK_ID=313, has rolled back the first two (releasing the locks) and has just that row locked now.
Session 2 – Connected as TESTUSER
Session 2 hangs, waiting for the lock.
Session 1 – Connected as TESTUSER
So the lock is released and session 2 acquires the lock and then releases it
Session 2 – Connected as Testuser
OK, time to look at the ASH data for the last two minutes for TESTUSER sessions. (Note that I have added each session’s serial# to the query. Graham Wood corrected a statement I made in the last post …
… by pointing out that session_serial# would allow me to differentiate between different sessions where SID=148. I’ve updated the previous post to that effect.)
So what statement is SQL_ID ‘95k0s60jznz76’?
Let’s face it, if you were to look at this data, how likely is it that you would think that that statement was responsible for blocking session 2, when it wasn't?
No sooner had I finished part 3 with some conclusions than I thought of another example I should have included and then someone else made a comment in an email which suggested another. (Thanks, JB!)
"It's probably worth pointing out that NO TOOL can claim to identify the blocking SID->SQL in such a case as there is no relationship kept in Oracle between locks acquired by users and the SQL that acquired the locks"
I’ll try to deal with that point and some other thoughts I had here in a further example. For this example, I decided to suggest how to create a quick table so that you can test this out for yourself.
SQL> create user testuser identified by testuser 2 default tablespace USERS 3 temporary tablespace TEMP; User created. SQL> grant create session, create table to testuser; Grant succeeded. SQL> connect testuser/testuser Connected. SQL> create table test_tab1 as select object_id pk_id, object_name from all_objects; Table created.
As easy as that.
In the last part I showed that the SQL_ID for the last sample of a blocking session immediately before it went idle might not be the SQL statement holding the lock. In that case, it was fairly obvious that it wasn’t because it was a simple query that couldn’t have been responsible. However, it’s likely to be even more confusing if the SQL_ID captured by the ASH sample *looks* like it’s responsible, but isn’t, and the previous example didn't illustrate that clearly.
Session 1 – Connected as TESTUSER
SQL> select pk_id, object_name from test_tab1 order by pk_id desc for update; <Trimmed> 890 DBMS_STANDARD 889 DBMS_STANDARD PK_ID OBJECT_NAME ---------- ------------------------------ 887 STANDARD 886 RE$NV_LIST 605 MAP_OBJECT 319 STMT_AUDIT_OPTION_MAP 317 STMT_AUDIT_OPTION_MAP 316 TABLE_PRIVILEGE_MAP 314 TABLE_PRIVILEGE_MAP 313 SYSTEM_PRIVILEGE_MAP 311 SYSTEM_PRIVILEGE_MAP 259 DUAL 258 DUAL 4477 rows selected. SQL> rollback; Rollback complete. SQL> select pk_id from test_tab1 where object_name='SYSTEM_PRIVILEGE_MAP' for update; PK_ID ---------- 311 313 SQL> rollback; Rollback complete. SQL> select pk_id from test_tab1 where pk_id=313 for update; PK_ID ---------- 313 SQL>
So session 1 has executed three different queries, all of which lock one or more rows including the row with PK_ID=313, has rolled back the first two (releasing the locks) and has just that row locked now.
Session 2 – Connected as TESTUSER
SQL> select pk_id from test_tab1 where pk_id=313 for update;
Session 2 hangs, waiting for the lock.
Session 1 – Connected as TESTUSER
SQL> rollback; Rollback complete.
So the lock is released and session 2 acquires the lock and then releases it
Session 2 – Connected as Testuser
PK_ID ---------- 313 SQL> rollback; Rollback complete.
OK, time to look at the ASH data for the last two minutes for TESTUSER sessions. (Note that I have added each session’s serial# to the query. Graham Wood corrected a statement I made in the last post …
“who is to say that that session 148 is the same session as the blocking session 148 and not an earlier session that has disconnected?”
… by pointing out that session_serial# would allow me to differentiate between different sessions where SID=148. I’ve updated the previous post to that effect.)
break on MY_TIME column my_sid format 999 column my_ser format 99999 column my_state format a30 column my_blkr format 999 select to_char(a.sample_time, 'HH24:MI:SS') MY_TIME,a.session_id MY_SID,a.session_serial# MY_SER, DECODE(a.session_state, 'WAITING' ,a.event, a.session_state) MY_STATE,a.xid, a.sql_id, a.blocking_session MY_BLKR from v$active_session_history a, dba_users u where u.user_id = a.user_id and u.username = 'TESTUSER' and a.sample_time > SYSTIMESTAMP-(2/1440); MY_TIME MY_SID MY_SER MY_STATE XID SQL_ID MY_BLKR -------- ------ ------ ------------------------------ ---------------- ------------- ------- 12:53:01 300 2739 enq: TX - row lock contention 2pa7rnqf65gj3 304 12:53:00 300 2739 enq: TX - row lock contention 2pa7rnqf65gj3 304 12:52:59 300 2739 enq: TX - row lock contention 2pa7rnqf65gj3 304 12:52:50 304 1445 ON CPU 0006000E0000884D 95k0s60jznz76
So what statement is SQL_ID ‘95k0s60jznz76’?
SQL> select sql_text from v$sql where sql_id='95k0s60jznz76'; SQL_TEXT ----------------------------------------------------------------------------- select pk_id, object_name from test_tab1 order by pk_id desc for update
Let’s face it, if you were to look at this data, how likely is it that you would think that that statement was responsible for blocking session 2, when it wasn't?
Posted by Doug Burns
Comments: (0)
Trackbacks: (5)
Related entries by tags:
Network Events in ASH
Alternative Pictures Demo
That Pictures demo in full
Diagnosing Locking Problems using ASH/LogMiner – The End
Diagnosing Locking Problems using ASH/LogMiner – Part 9
Diagnosing Locking Problems using ASH/LogMiner – Part 8
Diagnosing Locking Problems using ASH/LogMiner – Part 7
Diagnosing Locking Problems using ASH – Part 6
Diagnosing Locking Problems using ASH – Part 5
Diagnosing Locking Problems using ASH - Part 3
Network Events in ASH
Alternative Pictures Demo
That Pictures demo in full
Diagnosing Locking Problems using ASH/LogMiner – The End
Diagnosing Locking Problems using ASH/LogMiner – Part 9
Diagnosing Locking Problems using ASH/LogMiner – Part 8
Diagnosing Locking Problems using ASH/LogMiner – Part 7
Diagnosing Locking Problems using ASH – Part 6
Diagnosing Locking Problems using ASH – Part 5
Diagnosing Locking Problems using ASH - Part 3
"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 ta
Tracked: Apr 20, 20:20
So what about those SELECT FOR UPDATEs?I know that they’ll 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’ll go back to
Tracked: Apr 23, 09:43
Tracked: May 15, 10:24
Tracked: Aug 15, 12:59
Tracked: Jul 25, 16:32