Archive

Archive for April, 2011

Influence of new Oracle version – well actually not

22/04/2011 Leave a comment

Recently I have been working on application testing  related to a migration from 10.2.0.3 to 11.1.0.7.  New hardware as well. More and faster CPUs and significantly faster IO created some expectations.

So (as usual) some significantly slower batch jobs  were a bad, but somewhat expected surprise. Here is one example:

A batch job took 37 minutes instead of 15 minutes. I took one of the worst performing statements, taking 270 instead of 60 seconds, to investigate. Rather quickly the usual suspects, such as a changed plan, could be ruled out. As a matter of fact, after a while I could reduce the statement to a simple  reproducible test.

Preparation:


create table testsz
(i number, wa varchar2(5), vt varchar2(1), v varchar2(400));

create table testsz2
(i number, wa varchar2(5), vt varchar2(1), v varchar2(400));
create index testsz2_i on testsz2(wa,vt);

insert into testsz
with gen as (select rownum rn  from dual connect by level<=1e5)
select mod(rn, 1000),
       case  mod(rn,3) when 0 then 'A' when 1 then 'B' when 2 then 'C' else 'D' end||mod(rn, 2000),
       case when mod(rn,1) =0 then 'Y' else 'Q' end,
       lpad('x',300,'x'
 from gen;
commit;

Test:

set timing on

truncate table testsz2;

insert into testsz2
  select *
   from testsz;

The exact times vary depending on system and hardware, but the difference was significant on all systems tested.

Results on 10g vs 11g:   5 seconds vs 20 seconds.

This bugged me quite some time. I did all kinds of really stupid and other non-relevant stuff to investigate, to no avail. There must be something wrong with Oracle, right?

Finally I detected a increase in FB enqueue contention on 11g.  So there must be something wrong with the new Oracle release, right?

Looking for bug reports like mad, nothing found. (Not that the increase actually was significant, and if it had not been on ASSM tablespaces it would have been different anyway). Still, this triggered me to remember, that I asked a few weeks ago, about a changed init setting. But did not bother to follow up. Quickly checked, luckily the parameter  is session modifiable:

Modified test, on 11g only:

set timing on

prompt block checking false
alter session set db_block_checking=false;
truncate table testsz2;

insert into testsz2
select * from testsz;

prompt block checking true
alter session set db_block_checking=true;
truncate table testsz2;

insert into testsz2
select * from testsz;

3 seconds vs 20 seconds. So this has nothing to do with the new oracle release, but a changed initialization parameter. I have not tested much further about the causes, but the difference is also there in 10g.  At least on the systems I have access to.

Obviously the db_block_checking setting has an overhead, but frankly I am surprised by the magnitude, considering the quotes in the oracle documentation (from 11.1):

Block checking typically causes 1% to 10% overhead, depending on workload and the parameter value. The more updates or inserts in a workload, the more expensive it is to turn on block checking. You should set DB_BLOCK_CHECKING to FULL if the performance overhead is acceptable.

That difference is certainly not acceptable to me. Anyone else seen such a big difference?

Categories: Performance, Trouble

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