Vishal desai’s Oracle Blog

December 9, 2011

Oracle Query Trasformation bug

Filed under: Bug — vishaldesai @ 12:16 am

Are you aware of any bugs in decode vs case behavior? One of my developer posed this open ended question to me other day. I asked him to send me sql code or test case.

Test Case

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for IBM/AIX RISC System/6000: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production 

SQL> create table table_1 as (select 'a' col1, 1 col2 from dual union select 'b' , 2  from dual );

Table created.

SQL> create table table_2 as (select 'a' col1, 1 col2 from dual union select 'b' , null  from dual);

Table created.

SQL>
SQL>
SQL> select * from table_1;

C       COL2
- ---------- 
a          1
b          2                                                                                                                                                                                            

SQL> select * from table_2;

C       COL2
- ---------- 
a          1
b                                                                                                                                                                                                       

SQL>
SQL> SELECT a.col1 acol1,
  2    a.col2 acol2,
  3    b.col1 bcol1,
  4    b.col2 bcol2 ,
  5    CASE
  6      WHEN 1 = 1
  7      THEN 'case breaks it'
  8    END case_breaks_it
  9  FROM
 10    (SELECT * FROM table_1) a,
 11    (SELECT col1, NVL(col2,0) col2 FROM table_2 ) b
 12  WHERE a.col1 = b.col1(+)
 13  AND a.col2   = b.col2(+);

A      ACOL2 B      BCOL2 CASE_BREAKS_IT
- ---------- - ---------- -------------- 
a          1 a          1 case breaks it
b          2            0 case breaks it                                                                                                                                                                

SQL>
SQL>
SQL>
SQL> SELECT a.col1 acol1,
  2    a.col2 acol2,
  3    b.col1 bcol1,
  4    b.col2 bcol2 ,
  5    DECODE(1,1,'decode works','this is strange') decode_doesnt
  6  FROM
  7    (SELECT * FROM table_1) a,
  8    (SELECT col1, NVL(col2,0) col2 FROM table_2) b
  9  WHERE a.col1 = b.col1(+)
 10  AND a.col2   = b.col2(+);

A      ACOL2 B      BCOL2 DECODE_DOESN
- ---------- - ---------- ------------ 
a          1 a          1 decode works
b          2              decode works

.

As you can see from above, BCOL2 column shows 0 when using case statement instead of null. Lets quickly look at run time query plan.

Query Plan

SQL> alter session set statistics_level=all;

Session altered.

SQL>
SQL> SELECT a.col1 acol1,
  2    a.col2 acol2,
  3    b.col1 bcol1,
  4    b.col2 bcol2 ,
  5    CASE
  6      WHEN 1 = 1
  7      THEN 'case breaks it'
  8    END case_breaks_it
  9  FROM
 10    (SELECT * FROM table_1) a,
 11    (SELECT col1, NVL(col2,0) col2 FROM table_2 ) b
 12  WHERE a.col1 = b.col1(+)
 13  AND a.col2   = b.col2(+);

A      ACOL2 B      BCOL2 CASE_BREAKS_IT
- ---------- - ---------- -------------- 
a          1 a          1 case breaks it
b          2            0 case breaks it                                                                                                                                                                

SQL> @xall

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  66rq1pmg8zyyy, child number 0
------------------------------------- 
SELECT a.col1 acol1,   a.col2 acol2,   b.col1 bcol1,   b.col2 bcol2 ,
CASE     WHEN 1 = 1     THEN 'case breaks it'   END case_breaks_it FROM
  (SELECT * FROM table_1) a,   (SELECT col1, NVL(col2,0) col2 FROM
table_2 ) b WHERE a.col1 = b.col1(+) AND a.col2   = b.col2(+)                                                                                                                                           

Plan hash value: 1294080186                                                                                                                                                                             

--------------------------------------------------------------------------------------------------------------------------------------------------- 
| Id  | Operation          | Name    | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
|   0 | SELECT STATEMENT   |         |      1 |        |       |    17 (100)|          |      2 |00:00:00.01 |       7 |       |       |          |
|*  1 |  HASH JOIN OUTER   |         |      1 |      2 |    88 |    17   (6)| 00:00:01 |      2 |00:00:00.01 |       7 |  1156K|  1156K|  535K (0)|
|   2 |   TABLE ACCESS FULL| TABLE_1 |      1 |      2 |    32 |     8   (0)| 00:00:01 |      2 |00:00:00.01 |       3 |       |       |          |
|   3 |   TABLE ACCESS FULL| TABLE_2 |      1 |      2 |    56 |     8   (0)| 00:00:01 |      2 |00:00:00.01 |       4 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------------------- 

Query Block Name / Object Alias (identified by operation id):
------------------------------------------------------------- 

   1 - SEL$5428C7F1                                                                                                                                                                                     

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   2 - SEL$5428C7F1 / TABLE_1@SEL$2
   3 - SEL$5428C7F1 / TABLE_2@SEL$3                                                                                                                                                                     

Outline Data
------------- 

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$5428C7F1")
      MERGE(@"SEL$2")
      MERGE(@"SEL$3")
      OUTLINE(@"SEL$1")
      OUTLINE(@"SEL$2")
      OUTLINE(@"SEL$3")
      FULL(@"SEL$5428C7F1" "TABLE_1"@"SEL$2")
      FULL(@"SEL$5428C7F1" "TABLE_2"@"SEL$3")
      LEADING(@"SEL$5428C7F1" "TABLE_1"@"SEL$2" "TABLE_2"@"SEL$3")
      USE_HASH(@"SEL$5428C7F1" "TABLE_2"@"SEL$3")
      END_OUTLINE_DATA
  */                                                                                                                                                                                                    

Predicate Information (identified by operation id):
--------------------------------------------------- 

   1 - access("TABLE_1"."COL1"="COL1" AND "TABLE_1"."COL2"=CASE  WHEN (ROWID IS NOT NULL) THEN NVL("COL2",0) ELSE NULL END )                                                                            

Column Projection Information (identified by operation id):
----------------------------------------------------------- 
   1 - (#keys=2) "TABLE_1"."COL1"[CHARACTER,1], "COL1"[CHARACTER,1], "TABLE_1"."COL2"[NUMBER,22], "COL2"[NUMBER,22]
   2 - "TABLE_1"."COL1"[CHARACTER,1], "TABLE_1"."COL2"[NUMBER,22]
   3 - ROWID[ROWID,10], "COL1"[CHARACTER,1], "COL2"[NUMBER,22]                                                                                                                                          

Note
----- 
   - dynamic sampling used for this statement (level=2)                                                                                                                                                 

63 rows selected.

SQL> SELECT a.col1 acol1,
  2    a.col2 acol2,
  3    b.col1 bcol1,
  4    b.col2 bcol2 ,
  5    DECODE(1,1,'decode works','this is strange') decode_doesnt
  6  FROM
  7    (SELECT * FROM table_1) a,
  8    (SELECT col1, NVL(col2,0) col2 FROM table_2) b
  9  WHERE a.col1 = b.col1(+)
 10  AND a.col2   = b.col2(+);

A      ACOL2 B      BCOL2 DECODE_DOESN
- ---------- - ---------- ------------ 
a          1 a          1 decode works
b          2              decode works                                                                                                                                                                  

SQL> @xall.sql

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  373cus15943ut, child number 0
------------------------------------- 
SELECT a.col1 acol1,   a.col2 acol2,   b.col1 bcol1,   b.col2 bcol2 ,
DECODE(1,1,'decode works','this is strange') decode_doesnt FROM
(SELECT * FROM table_1) a,   (SELECT col1, NVL(col2,0) col2 FROM
table_2) b WHERE a.col1 = b.col1(+) AND a.col2   = b.col2(+)                                                                                                                                            

Plan hash value: 1294080186                                                                                                                                                                             

--------------------------------------------------------------------------------------------------------------------------------------------------- 
| Id  | Operation          | Name    | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
|   0 | SELECT STATEMENT   |         |      1 |        |       |    17 (100)|          |      2 |00:00:00.01 |       7 |       |       |          |
|*  1 |  HASH JOIN OUTER   |         |      1 |      2 |    88 |    17   (6)| 00:00:01 |      2 |00:00:00.01 |       7 |  1156K|  1156K|  510K (0)|
|   2 |   TABLE ACCESS FULL| TABLE_1 |      1 |      2 |    32 |     8   (0)| 00:00:01 |      2 |00:00:00.01 |       3 |       |       |          |
|   3 |   TABLE ACCESS FULL| TABLE_2 |      1 |      2 |    56 |     8   (0)| 00:00:01 |      2 |00:00:00.01 |       4 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------------------- 

Query Block Name / Object Alias (identified by operation id):
------------------------------------------------------------- 

   1 - SEL$5428C7F1                                                                                                                                                                                     

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   2 - SEL$5428C7F1 / TABLE_1@SEL$2
   3 - SEL$5428C7F1 / TABLE_2@SEL$3                                                                                                                                                                     

Outline Data
------------- 

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$5428C7F1")
      MERGE(@"SEL$2")
      MERGE(@"SEL$3")
      OUTLINE(@"SEL$1")
      OUTLINE(@"SEL$2")
      OUTLINE(@"SEL$3")
      FULL(@"SEL$5428C7F1" "TABLE_1"@"SEL$2")
      FULL(@"SEL$5428C7F1" "TABLE_2"@"SEL$3")
      LEADING(@"SEL$5428C7F1" "TABLE_1"@"SEL$2" "TABLE_2"@"SEL$3")
      USE_HASH(@"SEL$5428C7F1" "TABLE_2"@"SEL$3")
      END_OUTLINE_DATA
  */                                                                                                                                                                                                    

Predicate Information (identified by operation id):
--------------------------------------------------- 

   1 - access("TABLE_1"."COL1"="COL1" AND "TABLE_1"."COL2"=CASE  WHEN (ROWID IS NOT NULL) THEN NVL("COL2",0) ELSE NULL END )                                                                            

Column Projection Information (identified by operation id):
----------------------------------------------------------- 
   1 - (#keys=2) "TABLE_1"."COL1"[CHARACTER,1], "COL1"[CHARACTER,1], "TABLE_1"."COL2"[NUMBER,22], ROWID[ROWID,10], "COL2"[NUMBER,22]
   2 - "TABLE_1"."COL1"[CHARACTER,1], "TABLE_1"."COL2"[NUMBER,22]
   3 - ROWID[ROWID,10], "COL1"[CHARACTER,1], "COL2"[NUMBER,22]                                                                                                                                          

Note
----- 
   - dynamic sampling used for this statement (level=2)

.

Query plans, Outline data and predicate information for both the plans are same but the column projection for query using decode with operation id 1 has additional column ROWID[ROWID,10]. But its not clear at this stage why Oracle needs ROWID from TABLE_2. Lets run 10053 trace to check query transformations.

10053

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT "TABLE_1"."COL1" "ACOL1","TABLE_1"."COL2" "ACOL2","TABLE_2"."COL1" "BCOL1",NVL("TABLE_2"."COL2",0) "BCOL2",'case breaks it' "CASE_BREAKS_IT" FROM "VDESAI"."TABLE_1" "TABLE_1","VDESAI"."TABLE_2" "TABLE_2" WHERE "TABLE_1"."COL1"="TABLE_2"."COL1"(+) AND "TABLE_1"."COL2"=CASE  WHEN ("TABLE_2".ROWID(+) IS NOT NULL) THEN NVL("TABLE_2"."COL2"(+),0) ELSE NULL END 

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT "TABLE_1"."COL1" "ACOL1","TABLE_1"."COL2" "ACOL2","TABLE_2"."COL1" "BCOL1",CASE  WHEN "TABLE_2".ROWID IS NOT NULL THEN NVL("TABLE_2"."COL2",0) ELSE NULL END  "BCOL2",'decode works' "DECODE_DOESNT" FROM "VDESAI"."TABLE_1" "TABLE_1","VDESAI"."TABLE_2" "TABLE_2" WHERE "TABLE_1"."COL1"="TABLE_2"."COL1"(+) AND "TABLE_1"."COL2"=CASE  WHEN ("TABLE_2".ROWID(+) IS NOT NULL) THEN NVL("TABLE_2"."COL2"(+),0) ELSE NULL END

.

From above its clear that Oracle optimizer is rewriting both queries little differently using query transformation. You cannot run this queries directly as there are some other variables applied to it internally during runtime. So running transformed query directly from sqlplus may not produce same result as the original query does.

To prevent query transformation, I tried to run query with case statement with NO_MERGE hint and it produced expected output. If you cannot change code set “_simple_view_merging” to false and you will get correct output.

NO_MERGE

VDESAI@csprod2 > select /*+ NO_MERGE(@"SEL$2") NO_MERGE(@"SEL$3") */ a.col1 acol1, a.col2 acol2, b.col1 bcol1, b.col2 bcol2
  2       ,case when 1 = 1 then 'case breaks it' end case_breaks_it
  3        from (select * from table_1) a,
  4             (select col1, nvl(col2,0) col2 from table_2) b
  5        where a.col1 = b.col1(+)
  6          and a.col2 = b.col2(+);

A      ACOL2 B      BCOL2 CASE_BREAKS_IT
- ---------- - ---------- --------------
a          1 a          1 case breaks it
b          2              case breaks it

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT "A"."COL1" "ACOL1","A"."COL2" "ACOL2","B"."COL1" "BCOL1","B"."COL2" "BCOL2",'case breaks it' "CASE_BREAKS_IT" FROM  (SELECT /*+ NO_MERGE */ "TABLE_1"."
COL1" "COL1","TABLE_1"."COL2" "COL2" FROM "VDESAI"."TABLE_1" "TABLE_1") "A", (SELECT /*+ NO_MERGE */ "TABLE_2"."COL1" "COL1",NVL("TABLE_2"."COL2",0) "COL2" FR
OM "VDESAI"."TABLE_2" "TABLE_2") "B" WHERE "A"."COL1"="B"."COL1"(+) AND "A"."COL2"="B"."COL2"(+)

---------------------------------------+-----------------------------------+
| Id  | Operation            | Name    | Rows  | Bytes | Cost  | Time      |
---------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT     |         |       |       |    17 |           |
| 1   |  HASH JOIN OUTER     |         |     2 |    64 |    17 |  00:00:01 |
| 2   |   VIEW               |         |     2 |    32 |     8 |  00:00:01 |
| 3   |    TABLE ACCESS FULL | TABLE_1 |     2 |    32 |     8 |  00:00:01 |
| 4   |   VIEW               |         |     2 |    32 |     8 |  00:00:01 |
| 5   |    TABLE ACCESS FULL | TABLE_2 |     2 |    32 |     8 |  00:00:01 |
---------------------------------------+-----------------------------------+
Predicate Information:
----------------------
1 - access("A"."COL1"="B"."COL1" AND "A"."COL2"="B"."COL2")

  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('_unnest_subquery' 'false')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$2")
      OUTLINE_LEAF(@"SEL$3")
      OUTLINE_LEAF(@"SEL$1")
      NO_ACCESS(@"SEL$1" "A"@"SEL$1")
      NO_ACCESS(@"SEL$1" "B"@"SEL$1")
      LEADING(@"SEL$1" "A"@"SEL$1" "B"@"SEL$1")
      USE_HASH(@"SEL$1" "B"@"SEL$1")
      FULL(@"SEL$2" "TABLE_1"@"SEL$2")
      FULL(@"SEL$3" "TABLE_2"@"SEL$3")
    END_OUTLINE_DATA
  */

. 

Advertisements

February 7, 2011

Hash Join Performance Bug on 11.2.0.2 AIX 6.1 64bit

Filed under: Bug, Uncategorized — vishaldesai @ 5:51 am

Problem

Development ETL team started complaining about performance after upgrading development database to 11.2.0.2 on AIX 64 bit. Good news was not everything is slow but few steps in ETL job was taking longer in 11g compared to that of 10g.  QA environment was on 10g with same amount of data as Development and I was able to reproduce slowness in 11g.

Trobleshooting

I first created a test case to reproduce and run some test quickly with smaller data set. Create tables in either 10g and 11g and them move data from 10g to 11g or vice a versa.



DROP TABLE hash_big; 

CREATE TABLE hash_big
  (
     uniq_n NUMBER,
     var_n  VARCHAR2(100),
     geozip VARCHAR2(3),
     proc   VARCHAR2(1)
  )
tablespace users; 

INSERT /*+append*/ INTO hash_big
SELECT ROWNUM,
       dbms_random.String('A', 20),
       Round(dbms_random.VALUE(0, 999)),
       'C'
FROM   dual
CONNECT BY LEVEL <= 11111111
/

DROP TABLE hash_small; 

CREATE TABLE hash_small
  (
     geozip VARCHAR2(3),
     begzip VARCHAR2(3),
     endzip VARCHAR2(3),
     proc   VARCHAR2(1)
  )
tablespace users; 

insert into hash_small values ('001','001','099','C');
insert into hash_small values ('101','101','199','C');
insert into hash_small values ('201','201','299','C');
insert into hash_small values ('301','301','399','C');
insert into hash_small values ('401','401','499','C');
insert into hash_small values ('501','501','599','C');
insert into hash_small values ('601','601','699','C');
insert into hash_small values ('701','701','799','C');
insert into hash_small values ('801','801','899','C');
insert into hash_small values ('901','901','999','C');
commit;

exec dbms_stats.gather_table_Stats('SYSTEM','HASH_SMALL');
exec dbms_stats.gather_table_Stats('SYSTEM','HASH_BIG');

select segment_name,blocks,bytes/1024/1024 from dba_segments
where segment_name in ('HASH_SMALL','HASH_BIG');

SEGMENT_NAME                                 BLOCKS BYTES/1024/1024
---------------------------------------- ---------- ---------------
HASH_BIG                                      29184             456
HASH_SMALL                                        8            .125

--Populate tables with data in only one database and then move data to another version of database to maintain consistency.
--Tables size in blocks and MB must be same in 10g and 11g

Test Queries:

select /*+ ordered parallel (s,4) parallel (b,4) */ count(1) from hash_small s, hash_big b
where s.proc=b.proc
and b.geozip between s.begzip and s.endzip;

select count(1) from hash_small s, hash_big b
where s.proc=b.proc
and b.geozip BETWEEN s.begzip and s.endzip;

I ran above select statments in parallel and serial mode 5 times from same session with autotrace on.

10g Parallel:

Elapsed          Consistent   Physical   Parse
00:00:16.43      29441        28813       Hard
00:00:15.05      28977        28761       Soft
00:00:14.73      28977        28761       Soft
00:00:14.76      28977        28761       Soft
00:00:15.75      28977        28761       Soft                                                                                             

11g Parallel:

Elapsed          Consistent Physical    Parse
00:00:22.48      29538      28813       Hard
00:00:20.01      29191      28763       Soft
00:00:19.83      29191      28763       Soft
00:00:19.99      29191      28763       Soft
00:00:19.82      29191      28763       Soft

10g Serial:

Elapsed          Consistent Physical    Parse
00:00:24.65      29043      28792       Hard
00:00:22.26      28783          0       Soft
00:00:22.85      28783          0       Soft
00:00:24.93      28783          0       Soft
00:00:22.34      28783          0       Soft

11g Serial:

Elapsed          Consistent Physical    Parse
00:00:32.68      29069      28800       Hard
00:00:32.75      28778      28763       Soft
00:00:32.56      28778      28763       Soft
00:00:32.45      28778      28763       Soft
00:00:32.25      28778      28763       Soft

From above results it shows queries in 11g are approximately 25% slower compared to that of 10g. In 11g serial mode physical reads remain high and that was due to _serial_direct_read=TRUE in 11g. Lets first filter through obvious things.

10g serial trace:

select count(1) from hash_small s, hash_big b
where s.proc=b.proc
and b.geozip BETWEEN s.begzip and s.endzip

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.07          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     15.23      30.26      28768      28783          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     15.24      30.34      28768      28783          0           1

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 5

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=28783 pr=28768 pw=0 time=30268579 us)
10805391   HASH JOIN  (cr=28783 pr=28768 pw=0 time=32424435 us)
     10    TABLE ACCESS FULL HASH_SMALL (cr=7 pr=6 pw=0 time=4061 us)
11111111    TABLE ACCESS FULL HASH_BIG (cr=28776 pr=28762 pw=0 time=4057 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                         2        0.00          0.00
  db file scattered read                        918        0.05          6.78
  SQL*Net message from client                     2        0.00          0.00

11g serial trace:

select count(1) from hash_small s, hash_big b
where s.proc=b.proc
and b.geozip BETWEEN s.begzip and s.endzip

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.26         10         61          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     20.63      35.33      28774      28778          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     20.67      35.60      28784      28839          0           1

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 5
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=28778 pr=28774 pw=0 time=35338639 us)
  10805391   10805391   10805391   HASH JOIN  (cr=28778 pr=28774 pw=0 time=35226688 us cost=9624 size=444327376 card=27770461)
        10         10         10    TABLE ACCESS FULL HASH_SMALL (cr=6 pr=6 pw=0 time=7968 us cost=3 size=100 card=10)
  11111111   11111111   11111111    TABLE ACCESS FULL HASH_BIG (cr=28772 pr=28768 pw=0 time=5462617 us cost=9070 size=66666666 card=11111111)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  Disk file operations I/O                        8        0.00          0.01
  db file sequential read                         4        0.00          0.00
  db file scattered read                          2        0.00          0.00
  direct path read                              116        0.04          1.32
  SQL*Net message from client                     2        0.00          0.00

From above its cleare that plans are same, cosistent and physical reads are almost same in 10g and 11g. Difference in elapsed time comes from CPU column during fetch. (15.24 seconds in 10g and 20.57 seconds in 11g). To rule out _serial_direct_read=TRUE, I increased _small_table_threshold to a large value and below were the results:

11g disable _serial_direct_read

SQL> alter session set "_small_table_threshold"=10000000;

Session altered.

Elapsed: 00:00:00.00
SQL> alter session set "_serial_direct_read"=false;

Session altered.

Elapsed: 00:00:00.01
SQL> select count(1) from hash_small s, hash_big b
  2  where s.proc=b.proc
  3  and b.geozip BETWEEN s.begzip and s.endzip;

  COUNT(1)
----------
  10805391

Elapsed: 00:00:49.15

Execution Plan
----------------------------------------------------------
Plan hash value: 753592804

----------------------------------------------------------------------------------
| Id  | Operation           | Name       | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |            |     1 |    16 |  9624   (8)| 00:02:15 |
|   1 |  SORT AGGREGATE     |            |     1 |    16 |            |          |
|*  2 |   HASH JOIN         |            |    27M|   423M|  9624   (8)| 00:02:15 |
|   3 |    TABLE ACCESS FULL| HASH_SMALL |    10 |   100 |     3   (0)| 00:00:01 |
|   4 |    TABLE ACCESS FULL| HASH_BIG   |    11M|    63M|  9070   (2)| 00:02:07 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("S"."PROC"="B"."PROC")
       filter("B"."GEOZIP">="S"."BEGZIP" AND "B"."GEOZIP"<="S"."ENDZIP")

Statistics
----------------------------------------------------------
         63  recursive calls
          0  db block gets
      28849  consistent gets
      28784  physical reads
          0  redo size
        210  bytes sent via SQL*Net to client
        236  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         10  sorts (memory)
          0  sorts (disk)
          1  rows processed

SQL> /

  COUNT(1)
----------
  10805391

Elapsed: 00:00:34.39

Execution Plan
----------------------------------------------------------
Plan hash value: 753592804

----------------------------------------------------------------------------------
| Id  | Operation           | Name       | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |            |     1 |    16 |  9624   (8)| 00:02:15 |
|   1 |  SORT AGGREGATE     |            |     1 |    16 |            |          |
|*  2 |   HASH JOIN         |            |    27M|   423M|  9624   (8)| 00:02:15 |
|   3 |    TABLE ACCESS FULL| HASH_SMALL |    10 |   100 |     3   (0)| 00:00:01 |
|   4 |    TABLE ACCESS FULL| HASH_BIG   |    11M|    63M|  9070   (2)| 00:02:07 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("S"."PROC"="B"."PROC")
       filter("B"."GEOZIP">="S"."BEGZIP" AND "B"."GEOZIP"<="S"."ENDZIP")

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
      28788  consistent gets
          0  physical reads
          0  redo size
        227  bytes sent via SQL*Net to client
        236  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

In 11g with soft parse and no physical reads it took almost same amount of time so earlier increase in CPU seconds on 11g was not due to more physical reads. My test case run only for few seconds so I don’t want to run procstack from AIX on my test case. So lets take a look at original code.

alter session enable parallel dml;

insert --+ parallel(ii,8) append
              into repos_hi_lo_neg_clnup_geo ii
select --+ ordered parallel(t1,8) parallel(gt,8) full(t1) full(gt)
                    t1.RCN_ID,
                    t1.error_flag,
                    t1.job_id,
                    t1.scb_id,
                    t1.sub_id,
                    t1.proc_type,
                    t1.proc,
                    t1.mod1,
                    t1.mod2,
                    t1.mdr_flag,
                    t1.alm_flag,
                    t1.provider_key,
                    t1.bill_id_key,
                    t1.patient_id_key,
                    t1.repos_stamp,
                    t1.line_no,
                    t1.charge,
                    t1.allowed_amt,
                    t1.quarter,
                    t1.rend_zip,
                    gt.geozip,
                     t1.row_id
              from  geozip_mv gt,repos_hi_lo_neg_cleanup t1
                                  where t1.proc_type=gt.proc_type
                                 and  t1.sub_rend_zip between gt.begzip and gt.endzip;

As it was DEV/QA environment I was able to run actual ETL jobs. Samples of procstack on one of the parallel slaves from 10g and 11g are as follows:

10g procstack samples:

$ procstack 62193776 | head -5
62193776: ora_p012_CSPRDPP1
0x00000001000f6ce8  sskgpwpost(??, ??, ??, ??) + 0x28
0x00000001000f43f0  skgpwpost(??, ??, ??, ??) + 0x10
0x0000000100113ba8  kslpsprns(??, ??, ??) + 0x128
0x000000010016c5b4  kskpthr(??, ??, ??) + 0x194
$ procstack 62193776 | head -5
62193776: ora_p012_CSPRDPP1
0x00000001000f6ce8  sskgpwpost(??, ??, ??, ??) + 0x28
0x00000001000f43f0  skgpwpost(??, ??, ??, ??) + 0x10
0x0000000100113ba8  kslpsprns(??, ??, ??) + 0x128
0x000000010016c5b4  kskpthr(??, ??, ??) + 0x194
$ procstack 62193776 | head -5
62193776: ora_p012_CSPRDPP1
0x0000000102b4de54  kxhrPUcompare(??, ??, ??, ??) + 0x2b4
0x0000000103a1ead4  qerhjWalkHashBucket(??, ??, ??) + 0xb4
0x0000000103a1e540  qerhjInnerProbeHashTable(??, ??) + 0x2c0
0x0000000103b497dc  kdstf0000001kmP(??, ??, ??, ??, ??, ??, ??, ??) + 0xfdc
$ procstack 62193776 | head -5
62193776: ora_p012_CSPRDPP1
0x00000001000f6ce8  sskgpwpost(??, ??, ??, ??) + 0x28
0x00000001000f43f0  skgpwpost(??, ??, ??, ??) + 0x10
0x0000000100113ba8  kslpsprns(??, ??, ??) + 0x128
0x000000010016c5b4  kskpthr(??, ??, ??) + 0x194
$ procstack 62193776 | head -5
62193776: ora_p012_CSPRDPP1
0x00000001000f6ce8  sskgpwpost(??, ??, ??, ??) + 0x28
0x00000001000f43f0  skgpwpost(??, ??, ??, ??) + 0x10
0x0000000100113ba8  kslpsprns(??, ??, ??) + 0x128
0x000000010016c5b4  kskpthr(??, ??, ??) + 0x194
$ procstack 62193776 | head -5
62193776: ora_p012_CSPRDPP1
0x00000001000f6ce8  sskgpwpost(??, ??, ??, ??) + 0x28
0x00000001000f43f0  skgpwpost(??, ??, ??, ??) + 0x10
0x0000000100113ba8  kslpsprns(??, ??, ??) + 0x128
0x000000010016c5b4  kskpthr(??, ??, ??) + 0x194

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                          1,458          12.3
ksdxexeotherwait                  3,700,589          43      0    0.4      Other
db file parallel write                1,505           8      6    0.1 System I/O
direct path read                      6,778           7      1    0.1   User I/O
PX qref latch                     4,494,867           6      0    0.0      Other

11g procstack samples:

$ procstack 9175324 | head -5
9175324: ora_p007_CSPRDDV1
0x00000001052da81c  rworofprVeryFastUnpackRow(??, ??, ??, ??, ??) + 0x33c
0x00000001073f2f34  kxhrUnpack(??, ??, ??, ??, ??) + 0x94
0x00000001073eb79c  qerhjWalkHashBucket(??, ??, ??) + 0x2fc
0x00000001073ec948  qerhjInnerProbeHashTable(??, ??) + 0x4a8
$ procstack 9175324 | head -5
9175324: ora_p007_CSPRDDV1
0x00000001052da6d4  rworofprVeryFastUnpackRow(??, ??, ??, ??, ??) + 0x1f4
0x00000001073f2f34  kxhrUnpack(??, ??, ??, ??, ??) + 0x94
0x00000001073eb79c  qerhjWalkHashBucket(??, ??, ??) + 0x2fc
0x00000001073ec948  qerhjInnerProbeHashTable(??, ??) + 0x4a8
$ procstack 9175324 | head -5
9175324: ora_p007_CSPRDDV1
0x00000001060f8d14  expepr(??) + 0x3d4
0x00000001060f88f8  expeal(??) + 0x18
0x00000001073eb7b0  qerhjWalkHashBucket(??, ??, ??) + 0x310
0x00000001073ec948  qerhjInnerProbeHashTable(??, ??) + 0x4a8
$ procstack 9175324 | head -5
9175324: ora_p007_CSPRDDV1
0x0000000101edd08c  evareo(??) + 0x2c
0x00000001060f8cdc  expepr(??) + 0x39c
0x00000001060f92c8  evaiand(??) + 0x48
0x00000001060f88f8  expeal(??) + 0x18
$ procstack 9175324 | head -5
9175324: ora_p007_CSPRDDV1
0x00000001060f8d00  expepr(??) + 0x3c0
0x00000001060f88f8  expeal(??) + 0x18
0x00000001073eb7b0  qerhjWalkHashBucket(??, ??, ??) + 0x310
0x00000001073ec948  qerhjInnerProbeHashTable(??, ??) + 0x4a8
$  procstack 9175324 | head -5
9175324: ora_p007_CSPRDDV1
0x00000001073f45f4  kxhrPUcompare(??, ??, ??, ??) + 0x334
0x00000001073ec948  qerhjInnerProbeHashTable(??, ??) + 0x4a8
0x000000010561f2b4  kdstf00000010000kmP(??, ??, ??, ??, ??, ??, ??, ??) + 0xa54
0x00000001055fb684  kdsttgr(??, ??, ??, ??, ??, ??, ??, ??) + 0xece4

                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                            1,876          11.6
ksdxexeotherwait                        220         118    535     .7 Other
direct path read                        451          33     73     .2 User I/O
Disk file operations I/O                564          12     21     .1 User I/O
control file sequential read          2,496           4      2     .0 System I/O

Again, query spend more time on CPU in 11g compared to that of 10g. 11g stack shows following functions:

rworofprVeryFastUnpackRow
expepr
evareo
kxhrPUcompare

I ran more samples in real time and most of the time procstack top function in 11g was from one of the above. I tried to search in metalink but couldn’t find exact description but from the name it looks like some kind of expression evaluation functions (expepr, kxhrPUcompare) which will be used by equality join as well as between clause. Further I ran test case queries by removing between clause as well as changing joining column fields to number field but results were same. I created SR using all these details and Oracle was able to reproduce this issue on their internal systems. As of now Oracle has filed this as bug 11689561.

Blog at WordPress.com.