hash join waits on cpu 100% time
From: GG <grzegorzof_at_interia.pl>
Date: Sat, 03 Jan 2015 19:33:18 +0100
Message-ID: <54A835EE.9070105_at_interia.pl>
Hi,
we are on 11.2.0.2
merge /*+ optimizer_features_enable='10.2.0.4'*/ into user1.tab_personal_add d using (with cm as (select /*+ no_parallel */ cm1.cust_id, cm1.cus_no, cm1.cunit_id, nvl(cpa.rec_checksum,0) rec_checksum from user1.TAB_MASTER cm1 full outer join
cm.cus_no and a.rec_checksum <> cm.rec_checksum ) f on ( d.cust_id =
| Elapsed | Cpu | IO | PL/SQL | Other | Buffer | Read | Read | Write | Write |
| Time(s) | Time(s) | Waits(s) | Time(s) | Waits(s) | Gets | Reqs | Bytes | Reqs | Bytes |
| 1005 | 895 | 0.18 | 0.00 | 110 | 5M | 20 | 5MB | 20 | 5MB |
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Mem | Activity | Activity Detail |
Date: Sat, 03 Jan 2015 19:33:18 +0100
Message-ID: <54A835EE.9070105_at_interia.pl>
Hi,
we are on 11.2.0.2
and observing strange issue with hash join , which waits on CPU all the time .
SQL> _at_snapper all 10 1 557
Sampling SID 557 with interval 10 seconds, taking 1 snapshots...
- Session Snapper v4.14 BETA - by Tanel Poder (
http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle
Troubleshooting Script on the Planet! :)
SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC,
%TIME, GRAPH , NUM_WAITS, WAITS/SEC, AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
557, SYS , STAT, session logical
reads , 47425, 5k,
, , , , 47,5k total buffer visits
557, SYS , STAT, consistent
gets , 47426,
5k, , , , , ~ per execution
557, SYS , STAT, consistent gets from
cache , 47426, 5k,
, , , , ~ per execution
557, SYS , STAT, consistent gets from cache
(fastpath) , 47426, 5k,
, , , , ~ per execution
557, SYS , STAT, calls to
kcmgcs , 150,
15,8, , , , , ~ per execution
557, SYS , STAT, no work - consistent read
gets , 47276, 4,98k,
, , , , ~ per execution
557, SYS , STAT, Cached Commit SCN
referenced , 1, ,11,
, , , , ~ per execution
557, SYS , STAT, table scans (short
tables) , 75, 7,9,
, , , , ~ per execution
557, SYS , STAT, table scan rows
gotten , 14843948,
1,56M, , , , , ~ per
execution
557, SYS , STAT, table scan blocks
gotten , 47276, 4,98k,
, , , , ~ per execution
557, SYS , STAT, buffer is pinned
count , 73, 7,69,
, , , , ,15 % buffer gets avoided
thanks to buffer pin caching
557, SYS , TIME, DB
CPU , 9340000,
984,04ms, 98.4%, [_at_@@@@@@@@@], , ,
557, SYS , TIME, sql execute elapsed
time , 10018685, 1,06s, 105.6%,
[##########], , ,
557, SYS , TIME, DB
time , 10018685,
1,06s, 105.6%, [##########], , , -5,55 % unaccounted time
Plan is rather usual and estimated vs actual rows are close .
Any ideas ?
QL Text
merge /*+ optimizer_features_enable='10.2.0.4'*/ into user1.tab_personal_add d using (with cm as (select /*+ no_parallel */ cm1.cust_id, cm1.cus_no, cm1.cunit_id, nvl(cpa.rec_checksum,0) rec_checksum from user1.TAB_MASTER cm1 full outer join
user1.tab_personal_add cpa on cm1.cust_id = cpa.cust_id where cm1.cunit_id = 2) select cm.cust_id, a.* from cdwmain.V_sa_tab_personal_add a, cm where a.time =to_date('20150102','yyyymmdd') and a.exported = '0' and a.cunit_id = cm.cunit_id and a.cus_no =
cm.cus_no and a.rec_checksum <> cm.rec_checksum ) f on ( d.cust_id =
f.cust_id ) when matched then update set d.cunit_id = f.cunit_id, d.title = f.title, d.gender = f.gender, d.birth_date = f.birth_date, d.birth_place = f.birth_place, d.type_doc = f.type_doc, d.id_number = f.id_number, d.nr_id = f.nr_id, d.nip = f.nip, d.fathers_name = f.fathers_name, d.maiden_name = f.maiden_name, d.mother_maiden = f.mother_maiden, d.marital_stat = f.marital_stat, d.spec_sign = f.spec_sign, d.inst_death = f.inst_death, d.add_info = f.add_info, d.b_dep_no = f.b_dep_no, d.numochildren = f.numochildren, d.cur_no = f.curr_no, d.inputter = f.inputter, d.authoriser = f.authoriser, d.auditor = f.auditor_code, d.audit_time = f.audit_date_time, d.glob_rec_date = f.input_date_time, d.glob_last_wday = f.Time, d.record_status = f.record_status, d.co_code= f.co_code, d.dept_code = f.dept_code, d.load_last_action = 'U', d.load_date = to_date('20150102','yyyymmdd'), d.load_time = SYSTIMESTAMP, d.cont_pref =
f.cont_pref, d.cont_type = f.cont_type, d.work_place = f.work_place, d.income = f.income, d.act_size = f.act_size, d.perm_no = f.perm_no, d.perm_valid = f.perm_valid, d.profession = f.profession, d.rec_checksum= f.rec_checksum when not matched then insert /* + append */ (
d.cust_id, d.cunit_id, d.title, d.gender, d.birth_date, d.birth_place,
d.type_doc, d.id_number, d.nr_id, d.nip, d.fathers_name, d.maiden_name,
d.mother_maiden, d.marital_stat, d.spec_sign, d.inst_death, d.add_info,
d.b_dep_no, d.numochildren, d.cur_no, d.inputter, d.authoriser,
d.auditor, d.audit_time, d.glob_rec_date, d.glob_last_wday,
d.record_status, d.co_code, d.dept_code, d.load_last_action,
d.load_date, d.load_time, d.cont_pref, d.cont_type, d.work_place,
d.income, d.act_size, d.perm_no, d.perm_valid, d.profession,
d.rec_checksum) values ( f.cust_id, f.cunit_id, f.title, f.gender,
f.birth_date, f.birth_place, f.type_doc, f.id_number, f.nr_id, f.nip,
f.fathers_name, f.maiden_name, f.mother_maiden,
f.marital_stat, f.spec_sign, f.inst_death, f.add_info, f.b_dep_no,
f.numochildren, f.curr_no, f.inputter, f.authoriser, f.auditor_code,
f.audit_date_time, f.input_date_time, f.Time, f.record_status,
f.co_code, f.dept_code, 'I', to_date('20150102','yyyymmdd'),
SYSTIMESTAMP, f.cont_pref, f.cont_type, f.work_place, f.income,
f.act_size, f.perm_no, f.perm_valid, f.profession, f.rec_checksum )
Global Information
Status : EXECUTING Instance ID : 1 Session : SYS (557:4349) SQL ID : f57f0s4zd9b58 SQL Execution ID : 16777216 Execution Started : 01/03/2015 18:50:54 First Refresh Time : 01/03/2015 18:51:02 Last Refresh Time : 01/03/2015 19:07:39 Duration : 1005s Module/Action : sqlplus_at_prod (TNS V1-V3)/- Service : SYS$USERS Program : sqlplus_at_prod (TNS V1-V3)
Global Stats
| Elapsed | Cpu | IO | PL/SQL | Other | Buffer | Read | Read | Write | Write |
| Time(s) | Time(s) | Waits(s) | Time(s) | Waits(s) | Gets | Reqs | Bytes | Reqs | Bytes |
| 1005 | 895 | 0.18 | 0.00 | 110 | 5M | 20 | 5MB | 20 | 5MB |
SQL Plan Monitoring Details (Plan Hash Value=3437768513)
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Mem | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | | (%) | (# samples) | =========================================================================================================================================================================== | 0 | MERGE STATEMENT | | | | | | 1 | | | | | | 1 | MERGE | tab_personal_ADD | | | 986 | +8 | 1 | 0 | | | | | 2 | VIEW | | | | 986 | +8 | 1 | 92 | | | | | -> 3 | HASH JOIN | | 189K | 7641 | 1004 | +2 | 1 | 92 | 73M | 0.20 | Cpu (2) | | 4 | HASH JOIN OUTER | | 202K | 5093 | 8 | +1 | 1 | 202K | | 0.10 | Cpu (1) | | 5 | HASH JOIN OUTER | | 202K | 1283 | 1 | +8 | 1 | 202K | | | | | 6 | PARTITION LIST SINGLE | | 202K | 611 | 1 | +8 | 1 | 202K | | | | | 7 | TABLE ACCESS FULL | TAB_MASTER | 202K | 611 | 1 | +8 | 1 | 202K | | | | | 8 | INDEX FAST FULL SCAN | I3_tab_personal_ADD | 1M | 360 | 1 | +8 | 1 | 1M | | | | | 9 | TABLE ACCESS FULL | tab_personal_ADD | 1M | 1457 | 1 | +8 | 1 | 1M | | | | | -> 10 | VIEW | V_SA_tab_personal_ADD | 189K | 321 | 998 | +8 | 1 | 7663 | | | | | -> 11 | TEMP TABLE TRANSFORMATION | | | | 998 | +8 | 1 | 7663 | | | | | 12 | LOAD AS SELECT | | | | 1 | +8 | 1 | 1 | | | | | 13 | TABLE ACCESS FULL | SA_CUS_CRM_PRIM_ADD | 198K | 162 | 1 | +8 | 1 | 198K | | | | | -> 14 | VIEW | | 189K | 159 | 998 | +8 | 1 | 7663 | | | | | -> 15 | UNION-ALL | | | | 998 | +8 | 1 | 7663 | | | | | 16 | FILTER | | | | | | 1 | | | | | | 17 | TABLE ACCESS FULL | SA_tab_personal_ADD | 668K | 660 | | | | | | | | | -> 18 | VIEW | | 198K | 26 | 1002 | +4 | 7664 | 7635 | | 84.56 | Cpu (849) | | -> 19 | TABLE ACCESS FULL | SYS_TEMP_0FD9EA7E0_1E010D37 | 198K | 26 | 998 | +8 | 7664 | 2G | | 4.58 | Cpu (46) | | -> 20 | TABLE ACCESS FULL | SA_tab_personal_ADD | 189K | 159 | 998 | +8 | 1 | 7663 | | | | | 21 | VIEW | | 198K | 26 | | | | | | | | | 22 | TABLE ACCESS FULL | SYS_TEMP_0FD9EA7E0_1E010D37 | 198K | 26 | | | | | | | | | 23 | FILTER | | | | | | | | | | | | 24 | TABLE ACCESS BY INDEX ROWID | SA_tab_personal_ADD | 1 | 4 | | | | | | | | | 25 | INDEX RANGE SCAN | SA_tab_personal_ADD_PKEY | 1 | 3 | | | | | | | | | 26 | VIEW | | 198K | 26 | | | | | | | | | 27 | TABLE ACCESS FULL | SYS_TEMP_0FD9EA7E0_1E010D37 | 198K | 26 | | | | | | | | | 28 | FILTER | | | | | | | | | | | | 29 | TABLE ACCESS BY INDEX ROWID | SA_tab_personal_ADD | 1 | | | | | | | | | | 30 | INDEX RANGE SCAN | SA_tab_personal_ADD_PKEY | 1 | | | | | | | | | ===========================================================================================================================================================================
-- http://www.freelists.org/webpage/oracle-lReceived on Sat Jan 03 2015 - 19:33:18 CET