Archive

Archive for 16/04/2011

Consistent get trace file parser

16/04/2011 Leave a comment

Similar to my last post, this relates to another posting  http://hoopercharles.wordpress.com/2011/01/24/watching-consistent-gets-10200-trace-file-parser. Tracing the event 10200 allows to see consistent reads. For details read linked blog entry. So now I also learned how to quote source code and < and >.

My contribution to the topic, added as comment in above mentioned post, a small awk script, that allows direct parsing of the trace file output on unix (although, I actually used it on cygwin …., so may be not 100% compatible).

In order to change to another trace file format, you just have to change $nr references in the script.

$ more cons_get_trc.awk

BEGIN {
   FS ="[ \t<>:]+"
    print "Details for file: " trcfile
   print "---------------------------------"
   while( getline < trcfile != EOF ){
      if ( $0 ~ /started for block/ ) {
      rdba[$6]+=1
      obj[$8]+=1
      both[$6","$8]+=1
      print $6 " " rdba[$6] ", " $8 " " obj[$8]
      }
   }
   close (trcfile)
   print ""

   print ""
   print "Summary rdba and obj for file: " trcfile
   print "---------------------------------"
   for ( var in both) {
      print var " " both[var]
   }

   print ""
   print "Summary obj for file: " trcfile
   print "---------------------------------"
   for ( var in obj ) {
      print var " " obj[var]
   }
}

One third code, two thirds output. Usage demonstration,  with just head -50 of a trace file into small.trc.  (header info removed below)


Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
.......

ktrget2(): started for block  <0x0104 : 0x09e3d4cc> objd: 0x00189fa5
env: (scn: 0x05b5.3bb87c76  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 97sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)
ktrexf(): returning 9 on:  10a102abc  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
ktrgcm(): completed for block  <0x0104 : 0x09e3d4cc> objd: 0x00189fa5
ktrget2(): completed for  block <0x0104 : 0x09e3d4cc> objd: 0x00189fa5
ktrget2(): started for block  <0x0104 : 0x09fa4692> objd: 0x00189fa5
env: (scn: 0x05b5.3bb87c76  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)
ktrexf(): returning 9 on:  10a102abc  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
ktrgcm(): completed for block  <0x0104 : 0x09fa4692> objd: 0x00189fa5
ktrget2(): completed for  block <0x0104 : 0x09fa4692> objd: 0x00189fa5
ktrget2(): started for block  <0x0104 : 0x0a0ac450> objd: 0x00189fa5
env: (scn: 0x05b5.3bb87c76  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)
ktrexf(): returning 9 on:  10a102abc  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
ktrgcm(): completed for block  <0x0104 : 0x0a0ac450> objd: 0x00189fa5
ktrget2(): completed for  block <0x0104 : 0x0a0ac450> objd: 0x00189fa5
ktrget2(): started for block  <0x0104 : 0x009d94fc> objd: 0x00189fa5
env: (scn: 0x05b5.3bb87c76  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)
ktrexf(): returning 9 on:  10a102abc  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
ktrgcm(): completed for block  <0x0104 : 0x009d94fc> objd: 0x00189fa5
ktrget2(): completed for  block <0x0104 : 0x009d94fc> objd: 0x00189fa5
ktrget2(): started for block  <0x0104 : 0x09fa4698> objd: 0x00189fa5
env: (scn: 0x05b5.3bb87c76  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)
ktrexf(): returning 9 on:  10a102abc  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
ktrgcm(): completed for block  <0x0104 : 0x09fa4698> objd: 0x00189fa5
ktrget2(): completed for  block <0x0104 : 0x09fa4698> objd: 0x00189fa5
ktrget2(): started for block  <0x0104 : 0x009d94ff> objd: 0x00189fa5
env: (scn: 0x05b5.3bb87c76  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 96sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)

$ awk -v trcfile=small.trc -f cons_get_trc.awk

Details for file: small.trc
---------------------------------
0x09e3d4cc 1, 0x00189fa5 1
0x09fa4692 1, 0x00189fa5 2
0x0a0ac450 1, 0x00189fa5 3
0x009d94fc 1, 0x00189fa5 4
0x09fa4698 1, 0x00189fa5 5
0x009d94ff 1, 0x00189fa5 6

Summary rdba and obj for file: small.trc
---------------------------------
0x0a0ac450,0x00189fa5 1
0x09fa4698,0x00189fa5 1
0x09fa4692,0x00189fa5 1
0x009d94ff,0x00189fa5 1
0x009d94fc,0x00189fa5 1
0x09e3d4cc,0x00189fa5 1

Summary obj for file: small.trc
---------------------------------
0x00189fa5 6

Categories: Tracing

TM enqueues and deadlock with one user session

16/04/2011 2 comments

For quite some time now, I have been thinking about writing some blog items, but never did. A recent blog entry on http://jonathanlewis.wordpress.com/2011/04/08/deadlock prompted me to give it a try.

So the first post is just a repetition of the comment I made:

TM-enqueues for foreign key locking seems to be a well known fact. What I personally would like to know, what other reasons can cause TM-Locks.
A few times already I had issues with them, not involving foreign keys.

Another reason are exclusive lock and the following. Did anyone know, that a single user connected session can cause a deadlock?

on 10.2.0.3 and 11.1.0.7 verified:


DROP TABLE TESTSZ;
CREATE TABLE TESTSZ
( I NUMBER,
  K VARCHAR2(50));
 INSERT INTO TESTSZ
 SELECT MOD(ROWNUM,1000), LPAD(‘X’,40,’Y') FROM DUAL CONNECT BY ROWNUM < 1000000;
 COMMIT;

LOCK TABLE TESTSZ IN EXCLUSIVE MODE;
 INSERT INTO TESTSZ X
 WITH X1 AS  (SELECT /*+ no_PARALLEL(T) MATERIALIZE*/ 2000, K FROM TESTSZ T
 WHERE I=1)
 SELECT * FROM X1;
 rollback;

LOCK TABLE TESTSZ IN EXCLUSIVE MODE;
 set timing on
 INSERT INTO TESTSZ X
 WITH X1 AS (SELECT /*+ PARALLEL(T,4) MATERIALIZE*/ 2000, K FROM TESTSZ T
 WHERE I=1)
 SELECT * FROM X1;
 rollback;

Result of the last insert statement:

INSERT INTO TESTSZ X
*
FEHLER in Zeile 1:
ORA-12801: error signaled in parallel query server P000
ORA-00060: deadlock detected while waiting for resource

Before anyone complains there are more than one session involved,
yes, but the importance is only one “user” connected session.

Moving back to TM locks, in the case above with the factored subquery
in combination with parallel query, the deadlock occurs while the sessions
are trying to get TM-locks.

SID PROGRAM LAST_CALL_ET BLOCKING_SESSION EVENT SECONDS_IN_WAIT
116 sqlplus.exe               48        PX Deq: Parse Reply     3  WAITING
117 oracle@cyber-ora10 (P005) 48        PX Deq: Execution Msg   3  WAITING
128 oracle@cyber-ora10 (P004) 48        PX Deq: Execution Msg   3  WAITING
115 oracle@cyber-ora10 (P003) 48        PX Deq: Execution Msg   3  WAITING
129 oracle@cyber-ora10 (P002) 48  116   enq: TM – contention   48 WAITING
120 oracle@cyber-ora10 (P001) 48  116   enq: TM – contention   48 WAITING
136 oracle@cyber-ora10 (P000) 48  116   enq: TM – contention   48 WAITING

To finish, Oracle support agreed, that this is not supposed to happen. The workaround is to use the inline hint.

And to credit, this originally happened to a co-worker sitting two desks next to me.

Categories: Locking, Trouble
Follow

Get every new post delivered to your Inbox.