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

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-l
Received on Sat Jan 03 2015 - 19:33:18 CET

Original text of this message