{"id":1495,"date":"2009-05-01T12:00:00","date_gmt":"2009-05-01T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1495"},"modified":"2009-05-01T12:00:00","modified_gmt":"2009-05-01T12:00:00","slug":"diagnosing-locking-problems-using-ashlogminer-the-end","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2009\/05\/01\/diagnosing-locking-problems-using-ashlogminer-the-end\/","title":{"rendered":"Diagnosing Locking Problems using ASH\/LogMiner \u2013 The End"},"content":{"rendered":"

Except\u00a0it’s not the\u00a0end, of course. What I mean is\u00a0that I usually agree with\u00a0what Miladin Modrakovic said in one of his comments<\/a> on his first deadlock blog post<\/a>.<\/p>\n

“There is always way around.<\/em>“<\/p>\n

As I keep saying, there are many different ways of diagnosing locking problems. Which one works best\u00a0depends on the situation you’re faced with but I don’t think there’s an ‘end’ here, a single solution that works well in all circumstances.<\/p>\n

Currently occurring\u00a0problems<\/em> are easy. There’s locking information in V$SESSION, V$TRANSACTION, V$LOCK etc and you can probably<\/em> track down the SQL statement that’s caused the problem.<\/p>\n

Those in the past<\/em> are more difficult but, even in difficult cases, you’ll often be able to get close enough to work out what’s going on, particularly if you combine data from multiple sources – redo entries, ASH samples and AWR showing you what SQL was running when and so on. It becomes more difficult with a SELECT FOR UPDATE and no subsequent UPDATE, though, because the various tools available (e.g. Logminer) don’t always return what you’d expect when the data doesn’t actually change.<\/p>\n

If you can recreate the problem or it’s an ongoing problem that you expect to reoccur<\/em>, then you can enable various traces and\u00a0have lots of information that will help you solve most real world problems.<\/p>\n

But the specific challenge here was to see which SQL statement was responsible for a locking problem, after the fact, when you weren’t expecting the problem in the first place.<\/p>\n

I thought I’d give Miladin’s most recent post<\/a>\u00a0a try because it\u00a0contains another interesting strategy – Flashback queries. Deadlock problems are different, not least because you have the resulting trace file. So his example isn’t designed to address what I’ve been looking at here, but I thought I should give it a try, as suggested by Vlado here<\/a>.<\/p>\n

The example he uses is a deadlock situation caused by updates, but I’ll apply it to the specific example I’ve been using here. Three SELECT FOR UPDATE statements – which one was the blocker? This time I’ve created TEST_TAB2 with fewer rows, but the rest of the test is the same.<\/p>\n

SQL> create table test_tab2 \n\tas select object_id pk_id, object_name from all_objects where object_id < 400;
<\/p>
Table created.<\/p>
SQL> select * from test_tab2;<\/p>
\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n---------- ------------------------------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 258 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 259 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 314 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 316 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 317 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 319 STMT_AUDIT_OPTION_MAP<\/p>
8 rows selected.<\/p>
<\/p>
<\/p>
SQL> @doug1\nSQL> column xidusn format 999\nSQL> column xidslot format 999\nSQL> column xidsqn format 999999\nSQL> select pk_id, object_name from test_tab2 order by pk_id desc for update;<\/p>
\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n---------- ------------------------------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 319 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 317 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 316 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 314 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 259 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 258 DUAL<\/p>
8 rows selected.<\/p>
SQL> select start_time, xid, xidusn, xidslot,\n\u00a0 2\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')\n\u00a0 3\u00a0 from v$transaction\n\u00a0 4\u00a0 order by start_time;<\/p>
START_TIME\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XIDUSN XIDSLOT\u00a0 XIDSQN\u00a0 START_SCN TO_CHAR(STA\n-------------------- ---------------- ------ ------- ------- ---------- -----------\n05\/01\/09 11:53:36\u00a0\u00a0\u00a0 0003001F000087AA\u00a0\u00a0\u00a0\u00a0\u00a0 3\u00a0\u00a0\u00a0\u00a0\u00a0 31\u00a0\u00a0 34730\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0<\/p>
SQL> rollback;<\/p>
Rollback complete.<\/p>
SQL> select pk_id from test_tab2 where object_name='SYSTEM_PRIVILEGE_MAP' for update;<\/p>
\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313<\/p>
SQL> select start_time, xid, xidusn, xidslot,\n\u00a0 2\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')\n\u00a0 3\u00a0 from v$transaction\n\u00a0 4\u00a0 order by start_time;<\/p>
START_TIME\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XIDUSN XIDSLOT\u00a0 XIDSQN\u00a0 START_SCN TO_CHAR(STA\n-------------------- ---------------- ------ ------- ------- ---------- -----------\n05\/01\/09 11:53:37\u00a0\u00a0\u00a0 0006000500008EEE\u00a0\u00a0\u00a0\u00a0\u00a0 6\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 5\u00a0\u00a0 36590\u00a0\u00a0 85744191\u00a0\u00a0\u00a0\u00a0 51C5A3F<\/p>
SQL> rollback;<\/p>
Rollback complete.<\/p>
SQL> select pk_id from test_tab2 where pk_id=313 for update;<\/p>
\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313<\/p>
SQL> select start_time, xid, xidusn, xidslot,\n\u00a0 2\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')\n\u00a0 3\u00a0 from v$transaction\n\u00a0 4\u00a0 order by start_time;<\/p>
START_TIME\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XIDUSN XIDSLOT\u00a0 XIDSQN\u00a0 START_SCN TO_CHAR(STA\n-------------------- ---------------- ------ ------- ------- ---------- -----------\n05\/01\/09 11:53:37\u00a0\u00a0\u00a0 0002001900008F2E\u00a0\u00a0\u00a0\u00a0\u00a0 2\u00a0\u00a0\u00a0\u00a0\u00a0 25\u00a0\u00a0 36654\u00a0\u00a0 85744194\u00a0\u00a0\u00a0\u00a0 51C5A42<\/p><\/pre>\n
So Session 1 has one row locked and will block Session 2.<\/p>\n
SQL> @doug2\nSQL> column xidusn format 999\nSQL> column xidslot format 999\nSQL> column xidsqn format 999999\nSQL>\nSQL> select pk_id from test_tab2 where pk_id=313 for update;<\/pre>\n
I rollback Session 1<\/p>\n
SQL> rollback;
<\/p>
Rollback complete.<\/p><\/pre>\n
and Session 2 acquires the lock, then rolls back.<\/p>\n
\u00a0\u00a0\u00a0\u00a0 PK_ID\n----------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313
<\/p>
SQL>\nSQL> select start_time, xid, xidusn, xidslot,\n\u00a0 2\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 xidsqn, start_scn, to_char(start_scn, 'XXXXXXXXXX')\n\u00a0 3\u00a0 from v$transaction\n\u00a0 4\u00a0 order by start_time;<\/p>
START_TIME\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 XIDUSN XIDSLOT\u00a0 XIDSQN\u00a0 START_SCN TO_CHAR(STA\n-------------------- ---------------- ------ ------- ------- ---------- -----------\n05\/01\/09 11:53:39\u00a0\u00a0\u00a0 00040018000067E3\u00a0\u00a0\u00a0\u00a0\u00a0 4\u00a0\u00a0\u00a0\u00a0\u00a0 24\u00a0\u00a0 26595\u00a0\u00a0 85744197\u00a0\u00a0\u00a0\u00a0 51C5A45<\/p>
SQL>\nSQL> rollback;<\/p>
Rollback complete.<\/p><\/pre>\n
This is what comes back from Flashback queries.<\/p>\n
SQL> @miladin\nSQL> set echo on\nSQL>\nSQL> SELECT\u00a0\u00a0\u00a0\u00a0 VERSIONS_XID\n\u00a0 2\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_STARTTIME\n\u00a0 3\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_ENDTIME\n\u00a0 4\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_STARTSCN\n\u00a0 5\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_ENDSCN\n\u00a0 6\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_OPERATION\n\u00a0 7\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 pk_id, object_name\n\u00a0 8\u00a0 FROM\u00a0\u00a0 testuser.test_tab2 VERSIONS BETWEEN TIMESTAMP MINVALUE AND MAXVALUE\n\u00a0 9\u00a0 ORDER\u00a0 BY VERSIONS_STARTTIME;
<\/p>
VERSIONS_XID\n----------------\nVERSIONS_STARTTIME\n---------------------------------------------------------------------------\nVERSIONS_ENDTIME\n---------------------------------------------------------------------------\nVERSIONS_STARTSCN VERSIONS_ENDSCN V\u00a0\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n----------------- --------------- - ---------- ------------------------------<\/p>
<\/p>
\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 258 DUAL<\/p>
<\/p>
\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 259 DUAL<\/p>
<\/p>
\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 311 SYSTEM_PRIVILEGE_MAP<\/p>
<\/p>
\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 319 STMT_AUDIT_OPTION_MAP<\/p>
<\/p>
\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 314 TABLE_PRIVILEGE_MAP<\/p>
<\/p>
\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 316 TABLE_PRIVILEGE_MAP<\/p>
<\/p>
\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 317 STMT_AUDIT_OPTION_MAP<\/p>
<\/p>
\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 313 SYSTEM_PRIVILEGE_MAP<\/p>
\n8 rows selected.<\/p>
SQL>\nSQL> SELECT * FROM testuser.test_tab2\n\u00a0 2\u00a0 AS OF TIMESTAMP (SYSTIMESTAMP - INTERVAL '1' MINUTE);<\/p>
\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n---------- ------------------------------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 258 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 259 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 314 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 316 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 317 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 319 STMT_AUDIT_OPTION_MAP<\/p>
8 rows selected.<\/p>
SQL>\nSQL> -- Narrow to specific column\nSQL>\nSQL> SELECT versions_xid XID, versions_startscn START_SCN, versions_endscn END_SCN, \n\tversions_operation OPERATION, object_name\n\u00a0 2\u00a0 FROM testuser.test_tab2\n\u00a0 3\u00a0 VERSIONS BETWEEN SCN MINVALUE AND MAXVALUE\n\u00a0 4\u00a0 WHERE pk_id=313;<\/p>
XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 START_SCN\u00a0\u00a0\u00a0 END_SCN O OBJECT_NAME\n---------------- ---------- ---------- - ------------------------------\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 SYSTEM_PRIVILEGE_MAP<\/p><\/pre>\n
Not much in other words. To check what I’m doing, I COMMITed the final update from Session 1 (as opposed to rolling it back) and got what I’d hope to see, because there’s actually a different committed version of the data.<\/p>\n
SQL> @miladin\nSQL> set echo on\nSQL>\nSQL> SELECT\u00a0\u00a0\u00a0\u00a0 VERSIONS_XID\n\u00a0 2\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_STARTTIME\n\u00a0 3\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_ENDTIME\n\u00a0 4\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_STARTSCN\n\u00a0 5\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_ENDSCN\n\u00a0 6\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 VERSIONS_OPERATION\n\u00a0 7\u00a0 ,\u00a0\u00a0\u00a0\u00a0\u00a0 pk_id, object_name\n\u00a0 8\u00a0 FROM\u00a0\u00a0 testuser.test_tab2 VERSIONS BETWEEN TIMESTAMP MINVALUE AND MAXVALUE\n\u00a0 9\u00a0 ORDER\u00a0 BY VERSIONS_STARTTIME;
<\/p>
VERSIONS_XID\n----------------\nVERSIONS_STARTTIME\n---------------------------------------------------------------------------\nVERSIONS_ENDTIME\n---------------------------------------------------------------------------\nVERSIONS_STARTSCN VERSIONS_ENDSCN V\u00a0\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n----------------- --------------- - ---------- ------------------------------\n0002000A00008F4B\n01-MAY-09 12.04.39<\/p>
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 85744966\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 U\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 XID 3<\/p>
<\/p>
\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 259 DUAL<\/p>
<\/p>
\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 311 SYSTEM_PRIVILEGE_MAP<\/p>
<\/p>
\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 319 STMT_AUDIT_OPTION_MAP<\/p>
<\/p>
\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 314 TABLE_PRIVILEGE_MAP<\/p>
<\/p>
\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 316 TABLE_PRIVILEGE_MAP<\/p>
<\/p>
\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 317 STMT_AUDIT_OPTION_MAP<\/p>
<\/p>
\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 258 DUAL<\/p>
<\/p>
01-MAY-09 12.04.39\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 85744966\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 SYSTEM_PRIVILEGE_MAP<\/p>
\n9 rows selected.<\/p>
SQL>\nSQL> SELECT * FROM testuser.test_tab2\n\u00a0 2\u00a0 AS OF TIMESTAMP (SYSTIMESTAMP - INTERVAL '1' MINUTE);<\/p>
\u00a0\u00a0\u00a0\u00a0 PK_ID OBJECT_NAME\n---------- ------------------------------\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 258 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 259 DUAL\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 311 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 313 SYSTEM_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 314 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 316 TABLE_PRIVILEGE_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 317 STMT_AUDIT_OPTION_MAP\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 319 STMT_AUDIT_OPTION_MAP<\/p>
8 rows selected.<\/p>
SQL>\nSQL> -- Narrow to specific column\nSQL>\nSQL> SELECT versions_xid XID, versions_startscn START_SCN, versions_endscn END_SCN, \n\tversions_operation OPERATION, object_name\n\u00a0 2\u00a0 FROM testuser.test_tab2\n\u00a0 3\u00a0 VERSIONS BETWEEN SCN MINVALUE AND MAXVALUE\n\u00a0 4\u00a0 WHERE pk_id=313;<\/p>
XID\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 START_SCN\u00a0\u00a0\u00a0 END_SCN O OBJECT_NAME\n---------------- ---------- ---------- - ------------------------------\n0002000A00008F4B\u00a0\u00a0 85744966\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 U XID 3\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 85744966\u00a0\u00a0 SYSTEM_PRIVILEGE_MAP<\/p><\/pre>\n
So the problem is that although there’s some locking information for the SELECT FOR UPDATEs (see previous blog posts) they’re difficult to diagnose because there were no changes to the data.<\/p>\n
Ultimately, I like the way Graham Wood put it in an email, so I asked him if I could quote it here.<\/p>\n
“I may well have said that it was impossible to get from the V$ tables. The reason that it is impossible is that row locks exist only in the disk blocks, in the form of the ITL. This was a key part of the whole row level locking scheme as it meant that we did not have to maintain and configure a structure to contain lock information that could, at worse need one entry for every row in the database. The ITL cannot be extended to include a SQLID, or at least not without requiring a data migration to the new block structure.<\/em><\/p>\n
You may well say that tracing will give you the blocking SQL. Well if you happen to be tracing the blocking session from the start of the blocking txn, then it is true that the trace file contains the blocking statement. However there may be many hundreds or thousands of statements in the trace file and there is no method that can tell you which one, even though you might be able to reduce the ‘possibles’ list by analysis of object access by the various statements.<\/em><\/p>\n
As for the use of the XID. The XID is useful because it gives a finite limit to which operation may have caused the lock i.e the lock must have been caused by a statement that was in the same txn that the blocking session is in at the time that the\u00a0 waiter is blocked.”<\/em><\/p>\n
There’s a gap in the data block and redo data describing the transaction – no SQLID. By using various strategies you might be able to make an educated guess as to the source of the problem, but there’s no way to guarantee<\/em> that you have the correct statement. But with so many different possibilities to get you close to a diagnosis, I’m not sure having the SQLID in there would be very useful\u00a0– certainly not worth\u00a0amending the ITL\u00a0structure.<\/p>\n
This series of posts is already way out of control, I’ve got other things I want to post about\u00a0and I’m sort of bored\u00a0by myself 😉 so, no matter what other approaches crop up, the most I’ll be doing is linking to them!<\/p>\n","protected":false},"excerpt":{"rendered":"
Except\u00a0it’s not the\u00a0end, of course. What I mean is\u00a0that I usually agree with\u00a0what Miladin Modrakovic said in one of his comments on his first deadlock blog post. “There is always way around.“ As I keep saying, there are many different ways of diagnosing locking problems. Which one works best\u00a0depends on the situation you’re faced with… Continue reading Diagnosing Locking Problems using ASH\/LogMiner \u2013 The End<\/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-1495","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1477,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-1\/","url_meta":{"origin":1495,"position":0},"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":1495,"position":1},"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":1487,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/20\/diagnosing-locking-problems-using-ash-part-6\/","url_meta":{"origin":1495,"position":2},"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":1478,"url":"http:\/\/orcldoug.com\/blog\/2009\/03\/30\/diagnosing-locking-problems-using-ash-part-2\/","url_meta":{"origin":1495,"position":3},"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":1484,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/17\/diagnosing-locking-problems-using-ash-part-5\/","url_meta":{"origin":1495,"position":4},"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":1481,"url":"http:\/\/orcldoug.com\/blog\/2009\/04\/09\/diagnosing-locking-problems-using-ash-part-4\/","url_meta":{"origin":1495,"position":5},"title":"Diagnosing Locking Problems using ASH \u2013 Part 4","date":"April 9, 2009","format":false,"excerpt":"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!) \"It's probably worth pointing out that\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\/1495","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=1495"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1495\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1495"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1495"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1495"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}