This discussion is archived
1 Reply Latest reply: Jan 29, 2013 11:34 AM by Jonathan Lewis RSS

Understanding explain plan output

Yoav Newbie
Currently Being Moderated
Hi,
Version 11202.
Bellow is the output of tkprof against a statment which has cpu time = elapsed time =~3000 sec.
The statment is related to oracle EBS , but the question bellow is regarding the execution plan.
As you can see in the plan bellow most of the time is spend on the following step :
         0          0          0      TABLE ACCESS BY INDEX ROWID IBY_PMT_INSTR_USES_ALL (cr=44630892 pr=31557 pw=0 time=3075553107 us cost=3 size=95402360 card=2385059)
2059303280 2059303280 2059303280       INDEX RANGE SCAN IBY_PMT_INSTR_USES_ALL_N2 (cr=13320705 pr=104 pw=0 time=1459328515 us cost=2 size=0 card=8)(object id 14313388)
What i am trying to understand is why 2 billions rows (2059303280) has been accessed by the index IBY_PMT_INSTR_USES_ALL_N2
SQL> select table_name,num_rows,sample_size,last_analyzed from dba_tables where table_name='IBY_PMT_INSTR_USES_ALL';

TABLE_NAME NUM_ROWS SAMPLE_SIZE LAST_ANAL
------------------------------ ---------- ----------- ---------
IBY_PMT_INSTR_USES_ALL 2414470 241447 28-JAN-13

SQL> select table_name,distinct_keys,clustering_factor,num_rows,sample_size,last_analyzed from dba_indexes where index_name='IBY_PMT_INSTR_USES_ALL_N2';

TABLE_NAME DISTINCT_KEYS CLUSTERING_FACTOR NUM_ROWS SAMPLE_SIZE LAST_ANAL
------------------------------ ------------- ----------------- ---------- ----------- ---------
IBY_PMT_INSTR_USES_ALL 304515 267170 2407170 240717 28-JAN-13
The whole statment and is plan is as followed :
insert into iby_pmt_instr_uses_all (instrument_payment_use_id,payment_flow,
  ext_pmt_party_id,instrument_type,instrument_id,payment_function,
  order_of_preference,created_by,creation_date,last_updated_by,
  last_update_date,last_update_login,object_version_number,start_date,
  end_date,debit_auth_flag,debit_auth_method,debit_auth_reference,
  debit_auth_begin,debit_auth_end)select iby_pmt_instr_uses_all_s.nextval  ,
  'FUNDS_CAPTURE' ,iep.ext_payer_id ,'BANKACCOUNT' ,eba.ext_bank_account_id ,
  'CUSTOMER_PAYMENT' ,DECODE(cbi.primary_flag,'Y',1,10) ,:b0 ,SYSDATE ,:b0 ,
  SYSDATE ,:b2 ,1 ,cbi.start_date ,cbi.end_date ,'' ,'' ,'' ,'' ,''  from 
  iby_external_payers_all iep ,hz_cust_accounts hca ,hz_cust_site_uses_all 
  csu ,hz_cust_acct_sites_all cas ,hz_parties hzba ,hz_relationships hzr ,
  hz_code_assignments hcba ,hz_parties hzbb ,hz_organization_profiles hop ,
  hz_code_assignments hcbb ,iby_ext_bank_accounts eba ,
  ra_customer_banks_int_all cbi where 
  (((((((((((((((((((((((((((((((((((((((cbi.interface_status is null  and 
  cbi.request_id=:b3) and UPPER(cbi.bank_name)=UPPER(hzba.party_name)) and 
  hzba.party_id=hop.party_id) and SYSDATE between 
  TRUNC(hop.effective_start_date) and NVL(TRUNC(hop.effective_end_date),
  (SYSDATE+1))) and hcba.class_category='BANK_INSTITUTION_TYPE') and 
  hcba.class_code='BANK') and hcba.owner_table_name='HZ_PARTIES') and 
  hcba.owner_table_id=hzba.party_id) and cbi.bank_home_country=
  hop.home_country) and hzbb.party_id=hcbb.owner_table_id) and 
  hcbb.owner_table_name='HZ_PARTIES') and hcbb.class_category=
  'BANK_INSTITUTION_TYPE') and hcbb.class_code='BANK_BRANCH') and 
  nvl(hcbb.status,'A')='A') and hzbb.party_id=hzr.subject_id) and 
  hzba.party_id=hzr.object_id) and hzr.relationship_type='BANK_AND_BRANCH') 
  and hzr.relationship_code='BRANCH_OF') and hzr.status='A') and 
  hzr.subject_table_name='HZ_PARTIES') and hzr.subject_type='ORGANIZATION') 
  and hzr.object_table_name='HZ_PARTIES') and hzr.object_type='ORGANIZATION') 
  and UPPER(cbi.bank_branch_name)=UPPER(hzbb.party_name)) and hzbb.party_id=
  eba.branch_id) and hzba.party_id=eba.bank_id) and eba.bank_account_num=
  cbi.bank_account_num) and eba.currency_code=cbi.bank_account_currency_code) 
  and cbi.orig_system_customer_ref=hca.orig_system_reference) and 
  iep.cust_account_id=hca.cust_account_id) and iep.party_id=hca.party_id) and 
  ((cbi.orig_system_address_ref is null  and iep.org_id is null ) or 
  iep.org_id=cbi.org_id)) and ((cbi.orig_system_address_ref is null  and 
  iep.org_type is null ) or iep.org_type='OPERATING_UNIT')) and cbi.org_id=
  cas.org_id(+)) and nvl(iep.acct_site_use_id,(-1))=
  decode(cbi.orig_system_address_ref,null ,(-1),csu.site_use_id)) and 
  cbi.orig_system_address_ref=cas.orig_system_reference(+)) and 
  (csu.site_use_id=(select min(site_use_id)  from hz_cust_site_uses_all hcsua 
  where ((hcsua.cust_acct_site_id=cas.cust_acct_site_id and 
  hcsua.site_use_code='BILL_TO') and hcsua.status='A')) or csu.site_use_id is 
  null )) and cas.cust_acct_site_id=csu.cust_acct_site_id(+)) and  not exists 
  (select 'x'  from iby_pmt_instr_uses_all ipi where (((ipi.ext_pmt_party_id=
  iep.ext_payer_id and ipi.instrument_type='BANKACCOUNT') and 
  ipi.instrument_id=eba.ext_bank_account_id) and ipi.payment_function=
  'CUSTOMER_PAYMENT')))



call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1   3049.58    3080.23      31827   44696023       1587        1175
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2   3049.58    3080.23      31827   44696023       1587        1175

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 57  (APPS)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=44696030 pr=31827 pw=0 time=2870820188 us)
      1175       1175       1175   SEQUENCE  IBY_PMT_INSTR_USES_ALL_S (cr=44695967 pr=31774 pw=0 time=3270855802 us)
      1175       1175       1175    FILTER  (cr=44695960 pr=31774 pw=0 time=3270803657 us)
      1175       1175       1175     NESTED LOOPS ANTI (cr=44695844 pr=31774 pw=0 time=3270739008 us cost=251 size=497 card=1)
      1175       1175       1175      NESTED LOOPS  (cr=64952 pr=217 pw=0 time=2991575 us cost=248 size=457 card=1)
      1175       1175       1175       NESTED LOOPS  (cr=64827 pr=205 pw=0 time=2949382 us cost=245 size=423 card=1)
      1175       1175       1175        NESTED LOOPS OUTER (cr=63494 pr=205 pw=0 time=2921176 us cost=243 size=403 card=1)
      1175       1175       1175         NESTED LOOPS  (cr=63377 pr=205 pw=0 time=2893312 us cost=240 size=391 card=1)
      1175       1175       1175          NESTED LOOPS  (cr=61415 pr=205 pw=0 time=2850064 us cost=236 size=348 card=1)
     47434      47434      47434           NESTED LOOPS  (cr=57058 pr=205 pw=0 time=2565056 us cost=234 size=328 card=1)
     41203      41203      41203            NESTED LOOPS OUTER (cr=42422 pr=0 pw=0 time=581594 us cost=230 size=296 card=1)
     41203      41203      41203             HASH JOIN  (cr=1049 pr=0 pw=0 time=173751 us cost=229 size=277 card=1)
      2333       2333       2333              NESTED LOOPS  (cr=1013 pr=0 pw=0 time=32850 us)
      2333       2333       2333               NESTED LOOPS  (cr=825 pr=0 pw=0 time=22036 us cost=208 size=172 card=1)
       514        514        514                NESTED LOOPS  (cr=691 pr=0 pw=0 time=16378 us cost=206 size=88 card=1)
       514        514        514                 NESTED LOOPS  (cr=588 pr=0 pw=0 time=7190 us cost=95 size=2501 card=41)
       514        514        514                  TABLE ACCESS BY INDEX ROWID HZ_CODE_ASSIGNMENTS (cr=20 pr=0 pw=0 time=1716 us cost=10 size=1681 card=41)
       514        514        514                   INDEX RANGE SCAN HZ_CODE_ASSIGNMENTS_N1 (cr=7 pr=0 pw=0 time=464 us cost=4 size=0 card=164)(object id 464630)
       514        514        514                  TABLE ACCESS BY INDEX ROWID HZ_PARTIES (cr=568 pr=0 pw=0 time=2797 us cost=2 size=20 card=1)
       514        514        514                   INDEX UNIQUE SCAN HZ_PARTIES_U1 (cr=54 pr=0 pw=0 time=1059 us cost=1 size=0 card=1)(object id 421661)
       514        514        514                 TABLE ACCESS BY INDEX ROWID HZ_ORGANIZATION_PROFILES (cr=103 pr=0 pw=0 time=5913 us cost=3 size=27 card=1)
       514        514        514                  INDEX RANGE SCAN BZ_HZ_ORGANIZATION_PROFILE_N1 (cr=76 pr=0 pw=0 time=2873 us cost=2 size=0 card=1)(object id 9378840)
      2333       2333       2333                INDEX RANGE SCAN HZ_RELATIONSHIPS_N2 (cr=134 pr=0 pw=0 time=3962 us cost=1 size=0 card=1)(object id 11581198)
      2333       2333       2333               TABLE ACCESS BY INDEX ROWID HZ_RELATIONSHIPS (cr=188 pr=0 pw=0 time=7476 us cost=2 size=84 card=1)
      1175       1175       1175              TABLE ACCESS FULL RA_CUSTOMER_BANKS_INT_ALL (cr=36 pr=0 pw=0 time=9479 us cost=21 size=123375 card=1175)
     41203      41203      41203             TABLE ACCESS BY INDEX ROWID HZ_CUST_ACCT_SITES_ALL (cr=41373 pr=0 pw=0 time=304952 us cost=1 size=19 card=1)
     41203      41203      41203              INDEX UNIQUE SCAN HZ_CUST_ACCT_SITES_U2 (cr=170 pr=0 pw=0 time=93830 us cost=1 size=0 card=1)(object id 421730)
     47434      47434      47434            TABLE ACCESS BY INDEX ROWID IBY_EXT_BANK_ACCOUNTS (cr=14636 pr=205 pw=0 time=2375333 us cost=4 size=32 card=1)
     47434      47434      47434             INDEX RANGE SCAN IBY_EXT_BANK_ACCOUNTS_N6 (cr=3548 pr=94 pw=0 time=1112297 us cost=2 size=0 card=1)(object id 14313177)
      1175       1175       1175           TABLE ACCESS BY INDEX ROWID HZ_PARTIES (cr=4357 pr=0 pw=0 time=171450 us cost=2 size=20 card=1)
      1203       1203       1203            INDEX UNIQUE SCAN HZ_PARTIES_U1 (cr=3154 pr=0 pw=0 time=107886 us cost=1 size=0 card=1)(object id 421661)
      1175       1175       1175          TABLE ACCESS BY INDEX ROWID HZ_CODE_ASSIGNMENTS (cr=1962 pr=0 pw=0 time=41107 us cost=3 size=43 card=1)
      1175       1175       1175           INDEX RANGE SCAN HZ_CODE_ASSIGNMENTS_U2 (cr=1611 pr=0 pw=0 time=25716 us cost=2 size=0 card=1)(object id 14355645)
      1175       1175       1175         TABLE ACCESS BY INDEX ROWID HZ_CUST_SITE_USES_ALL (cr=117 pr=0 pw=0 time=14875 us cost=3 size=12 card=1)
      1175       1175       1175          INDEX RANGE SCAN HZ_CUST_SITE_USES_N1 (cr=86 pr=0 pw=0 time=10600 us cost=2 size=0 card=1)(object id 464289)
      1175       1175       1175        TABLE ACCESS BY INDEX ROWID HZ_CUST_ACCOUNTS (cr=1333 pr=0 pw=0 time=22634 us cost=2 size=20 card=1)
      1175       1175       1175         INDEX UNIQUE SCAN HZ_CUST_ACCOUNTS_U3 (cr=158 pr=0 pw=0 time=9307 us cost=1 size=0 card=1)(object id 9438627)
      1175       1175       1175       TABLE ACCESS BY INDEX ROWID IBY_EXTERNAL_PAYERS_ALL (cr=125 pr=12 pw=0 time=131366 us cost=3 size=34 card=1)
      1175       1175       1175        INDEX RANGE SCAN IBY_EXTERNAL_PAYERS_ALL_U2 (cr=109 pr=4 pw=0 time=51266 us cost=2 size=0 card=1)(object id 14313089)
         0          0          0      TABLE ACCESS BY INDEX ROWID IBY_PMT_INSTR_USES_ALL (cr=44630892 pr=31557 pw=0 time=3075553107 us cost=3 size=95402360 card=2385059)
2059303280 2059303280 2059303280       INDEX RANGE SCAN IBY_PMT_INSTR_USES_ALL_N2 (cr=13320705 pr=104 pw=0 time=1459328515 us cost=2 size=0 card=8)(object id 14313388)
      1000       1000       1000     SORT AGGREGATE (cr=116 pr=0 pw=0 time=39211 us)
      1000       1000       1000      TABLE ACCESS BY INDEX ROWID HZ_CUST_SITE_USES_ALL (cr=116 pr=0 pw=0 time=27041 us cost=4 size=22 card=1)
      1000       1000       1000       INDEX RANGE SCAN HZ_CUST_SITE_USES_N1 (cr=85 pr=0 pw=0 time=19027 us cost=3 size=0 card=1)(object id 464289)
  • 1. Re: Understanding explain plan output
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    Yoav wrote:
    and  not exists 
    (select 'x'  from iby_pmt_instr_uses_all ipi where (((ipi.ext_pmt_party_id=
    iep.ext_payer_id and ipi.instrument_type='BANKACCOUNT') and 
    ipi.instrument_id=eba.ext_bank_account_id) and ipi.payment_function=
    'CUSTOMER_PAYMENT')))
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
    0          0          0  LOAD TABLE CONVENTIONAL  (cr=44696030 pr=31827 pw=0 time=2870820188 us)
    1175       1175       1175   SEQUENCE  IBY_PMT_INSTR_USES_ALL_S (cr=44695967 pr=31774 pw=0 time=3270855802 us)
    1175       1175       1175    FILTER  (cr=44695960 pr=31774 pw=0 time=3270803657 us)
    1175       1175       1175     NESTED LOOPS ANTI (cr=44695844 pr=31774 pw=0 time=3270739008 us cost=251 size=497 card=1)
    1175       1175       1175      NESTED LOOPS  (cr=64952 pr=217 pw=0 time=2991575 us cost=248 size=457 card=1)
    ...
    0          0          0      TABLE ACCESS BY INDEX ROWID IBY_PMT_INSTR_USES_ALL (cr=44630892 pr=31557 pw=0 time=3075553107 us cost=3 size=95402360 card=2385059)
    2059303280 2059303280 2059303280       INDEX RANGE SCAN IBY_PMT_INSTR_USES_ALL_N2 (cr=13320705 pr=104 pw=0 time=1459328515 us cost=2 size=0 card=8)(object id 14313388)
    1000       1000       1000     SORT AGGREGATE (cr=116 pr=0 pw=0 time=39211 us)
    1000       1000       1000      TABLE ACCESS BY INDEX ROWID HZ_CUST_SITE_USES_ALL (cr=116 pr=0 pw=0 time=27041 us cost=4 size=22 card=1)
    1000       1000       1000       INDEX RANGE SCAN HZ_CUST_SITE_USES_N1 (cr=85 pr=0 pw=0 time=19027 us cost=3 size=0 card=1)(object id 464289)
    You have a "not exists" subquery that the optimizer has turned into a nested loop anti join.

    For each of the 1175 rows returned by the previous step Oracle does a range scan of what it thinks is the most appropriate index - the figures for cost (2) and card (8) at that line show that something has gone wrong with the optimizer's estimates, and for each of the 1175 prior rows it has acquired an average 1.7M index entries based on the index predicates, then visited the table and discarded resulting row.

    It looks as if the index is a bad choice of index - you need to check the index predicates for the plan - use dbms_xplan to pull it from memory; and check your indexes to see if there is a better one that the optimizer should have chosen

    Regards
    Jonathan Lewis

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points