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.
Finally after more than 6 months oracle support thinks patch 12596494 should fix hash join performance issue.
11g parallel before patch
Elapsed Consistent Physical Parse
00:00:09.95 25660 25290 Hard
00:00:09.01 25590 25290 Soft
00:00:08.93 25591 25290 Soft
00:00:09.65 25592 25290 Soft
00:00:09.53 25591 25290 Soft
11g parallel after patch
Elapsed Consistent Physical Parse
00:00:09.78 25663 25311 Hard
00:00:07.70 25593 25290 Soft
00:00:07.50 25593 25290 Soft
00:00:07.37 25593 25290 Soft
00:00:07.34 25593 25290 Soft
But wait, I still see issues with serial hash joins. Back to Oracle support for long pause….
Comment by vishal Desai — October 9, 2011 @ 12:06 am
Vishal – We too applied this patch on our AIX server and we do not see any improvement in runtime of our query. Did oracle come back with any solutions on your SR?
Comment by Tejal — May 15, 2012 @ 8:52 pm
Oracle support is working on it for past 1 year. I see improvement in parallel hash joins after applying the patch but there was no improvement in serial mode.
Comment by vishaldesai — May 15, 2012 @ 10:43 pm
Thanks for your reply. Our queries run in serial mode only.
Comment by Tejal — May 16, 2012 @ 2:38 am