This discussion is archived
10 Replies Latest reply: Feb 4, 2013 10:46 AM by VijayaraghavanKrishnan RSS

Query performance slow WHY

845641 Newbie
Currently Being Moderated
Its 11G R2 version, and query is performing very slow

SELECT OBJSTATE
FROM
SUB_CON_CALL_OFF WHERE SUB_CON_NO = :B2 AND CALL_OFF_SEQ = :B1
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      140      0.00       0.00          0          0          0           0
Execute 798747      8.34      14.01          0          4          0           0
Fetch   798747     22.22      35.54          0    7987470          0      798747
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1597634     30.56      49.56          0    7987474          0      798747

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 51     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      5  FILTER  (cr=50 pr=0 pw=0 time=239 us)
      5   NESTED LOOPS  (cr=40 pr=0 pw=0 time=164 us)
      5    NESTED LOOPS  (cr=30 pr=0 pw=0 time=117 us)
      5     TABLE ACCESS BY INDEX ROWID SUB_CON_CALL_OFF_TAB (cr=15 pr=0 pw=0 time=69 us)
      5      INDEX UNIQUE SCAN SUB_CON_CALL_OFF_PK (cr=10 pr=0 pw=0 time=41 us)(object id 59706)
      5     TABLE ACCESS BY INDEX ROWID SUB_CONTRACT_TAB (cr=15 pr=0 pw=0 time=42 us)
      5      INDEX UNIQUE SCAN SUB_CONTRACT_PK (cr=10 pr=0 pw=0 time=26 us)(object id 59666)
      5    INDEX UNIQUE SCAN USER_PROFILE_ENTRY_SYS_PK (cr=10 pr=0 pw=0 time=41 us)(object id 60891)
      5   INDEX UNIQUE SCAN USER_ALLOWED_SITE_PK (cr=10 pr=0 pw=0 time=36 us)(object id 60866)
      5    FAST DUAL  (cr=0 pr=0 pw=0 time=4 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  library cache lock                              1        0.00          0.00
  gc cr block 2-way                               3        0.00          0.00
  gc current block 2-way                          1        0.00          0.00
  gc cr multi block request                       4        0.00          0.00 
Edited by: 842638 on Feb 2, 2013 5:52 AM
  • 1. Re: Query performance slow WHY
    Osama_Mustafa Oracle ACE
    Currently Being Moderated
    How many rows are there in the tables?
    What indexes are defined on the table?
    Has the table been analyzed ??
  • 2. Re: Query performance slow WHY
    sb92075 Guru
    Currently Being Moderated
    842638 wrote:
    Its 11G R2 version, and query is performing very slow
    WRONG!
    SQL> select 50/1500000 from dual;
    
    50/1500000
    ----------
    .000033333
    query is FAST; just abused & executed 1,500,000+ times
    over what wall clock elapsed time was sqltrace active?

    >
    SELECT OBJSTATE
    FROM
    SUB_CON_CALL_OFF WHERE SUB_CON_NO = :B2 AND CALL_OFF_SEQ = :B1
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse      140      0.00       0.00          0          0          0           0
    Execute 798747      8.34      14.01          0          4          0           0
    Fetch   798747     22.22      35.54          0    7987470          0      798747
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   1597634     30.56      49.56          0    7987474          0      798747
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 51     (recursive depth: 1)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
    5  FILTER  (cr=50 pr=0 pw=0 time=239 us)
    5   NESTED LOOPS  (cr=40 pr=0 pw=0 time=164 us)
    5    NESTED LOOPS  (cr=30 pr=0 pw=0 time=117 us)
    5     TABLE ACCESS BY INDEX ROWID SUB_CON_CALL_OFF_TAB (cr=15 pr=0 pw=0 time=69 us)
    5      INDEX UNIQUE SCAN SUB_CON_CALL_OFF_PK (cr=10 pr=0 pw=0 time=41 us)(object id 59706)
    5     TABLE ACCESS BY INDEX ROWID SUB_CONTRACT_TAB (cr=15 pr=0 pw=0 time=42 us)
    5      INDEX UNIQUE SCAN SUB_CONTRACT_PK (cr=10 pr=0 pw=0 time=26 us)(object id 59666)
    5    INDEX UNIQUE SCAN USER_PROFILE_ENTRY_SYS_PK (cr=10 pr=0 pw=0 time=41 us)(object id 60891)
    5   INDEX UNIQUE SCAN USER_ALLOWED_SITE_PK (cr=10 pr=0 pw=0 time=36 us)(object id 60866)
    5    FAST DUAL  (cr=0 pr=0 pw=0 time=4 us)
    
    
    Elapsed times include waiting on following events:
    Event waited on                             Times   Max. Wait  Total Waited
    ----------------------------------------   Waited  ----------  ------------
    library cache lock                              1        0.00          0.00
    gc cr block 2-way                               3        0.00          0.00
    gc current block 2-way                          1        0.00          0.00
    gc cr multi block request                       4        0.00          0.00 
    Edited by: 842638 on Feb 2, 2013 5:52 AM
    Handle:     842638
    Status Level:     Newbie
    Registered:     Mar 8, 2011
    Total Posts:     150
    Total Questions:     77 (52 unresolved)

    why so MANY unanswered questions?
  • 3. Re: Query performance slow WHY
    Mark D Powell Guru
    Currently Being Moderated
    I agree with SB in that the query performance appears good and the real question is why the query was called 798747 times? It would appear that this query returns 1 and only 1 row per execution since the number of row returned matches the number of executions. Any chance that this query is called once per row for an outer driving cursor. If so, combining the two SQL statements into a sinble statement may be a better approach for reducing total process run time.

    Also if there is an outer driving cursor even though the total time spent on the inner query may exceed the outer query expense you want to make sure that it is well tuned along with any other queries executed within the driving cursor loop.

    Naturally there are other possible explanations of why the query is executed so often but since driving cursor loops are common programming constructs I though I would mention the above.

    HTH -- Mark D Powell --
  • 4. Re: Query performance slow WHY
    ranit B Expert
    Currently Being Moderated
    Hi Mark,

    Just have few basic doubts regarding the below query performance :
     call     count       cpu    elapsed       disk      query    current        rows
     ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     Parse      140      0.00       0.00          0          0          0           0
     Execute 798747      8.34      14.01          0          4          0           0
     Fetch   798747     22.22      35.54          0    7987470          0      798747
     ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     total   1597634     30.56      49.56          0    7987474          0      798747
     
     Misses in library cache during parse: 1
     Misses in library cache during execute: 1
     Optimizer mode: ALL_ROWS
     Parsing user id: 51     (recursive depth: 1)
     
     Rows     Row Source Operation
     -------  ---------------------------------------------------
           5  FILTER  (cr=50 pr=0 pw=0 time=239 us)
           5   NESTED LOOPS  (cr=40 pr=0 pw=0 time=164 us)
           5    NESTED LOOPS  (cr=30 pr=0 pw=0 time=117 us)
           5     TABLE ACCESS BY INDEX ROWID SUB_CON_CALL_OFF_TAB (cr=15 pr=0 pw=0 time=69 us)
           5      INDEX UNIQUE SCAN SUB_CON_CALL_OFF_PK (cr=10 pr=0 pw=0 time=41 us)(object id 59706)
           5     TABLE ACCESS BY INDEX ROWID SUB_CONTRACT_TAB (cr=15 pr=0 pw=0 time=42 us)
           5      INDEX UNIQUE SCAN SUB_CONTRACT_PK (cr=10 pr=0 pw=0 time=26 us)(object id 59666)
           5    INDEX UNIQUE SCAN USER_PROFILE_ENTRY_SYS_PK (cr=10 pr=0 pw=0 time=41 us)(object id 60891)
           5   INDEX UNIQUE SCAN USER_ALLOWED_SITE_PK (cr=10 pr=0 pw=0 time=36 us)(object id 60866)
           5    FAST DUAL  (cr=0 pr=0 pw=0 time=4 us)
     
     
     Elapsed times include waiting on following events:
       Event waited on                             Times   Max. Wait  Total Waited
       ----------------------------------------   Waited  ----------  ------------
       library cache lock                              1        0.00          0.00
       gc cr block 2-way                               3        0.00          0.00
       gc current block 2-way                          1        0.00          0.00
       gc cr multi block request                       4        0.00          0.00 
     
    
    1] How do you determine that this query performance is +ok+ ? 
    2] What is the actual need of checking the query performance this way?
    3] Is this the TKPROF output?
    4] How do you know that the query was +called+ 798747 times? the +execute+ shows 0 
    
    Could you please help me with this?
     
    Thanks.
    Ranit B.                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
  • 5. Re: Query performance slow WHY
    Mark D Powell Guru
    Currently Being Moderated
    Ranit, the COUNT column shows how many time the query was executed. Most of the other columns do not apply to the execute step: parse, execute, fetch. Fetch is where a cursor gets the rows. All SQL statements are cursors.

    See the following Oracle Support document on how to read tkprof output.
    Note: 760786.1 TKProf Interpretation (9i and above)

    Divide the number of seconds elapsed by the number of rows fetched and you can see the time to retrieve one row. Five leading zeroes. If you divide the total rows fetched by time you get better than 16K rows per second retrieved. That seems pretty good but remember you are fetching only one row per execution so the question is, why is the query executed so many times?

    The explain plans shows all three tables are accessed via indexes. You show basically no waits.

    HTH -- Mark D Powell --
  • 6. Re: Query performance slow WHY
    riedelme Expert
    Currently Being Moderated
    842638 wrote:
    SELECT OBJSTATE
    FROM
    SUB_CON_CALL_OFF WHERE SUB_CON_NO = :B2 AND CALL_OFF_SEQ = :B1

    Rows Row Source Operation
    ------- ---------------------------------------------------
    5 FILTER (cr=50 pr=0 pw=0 time=239 us)
    5 NESTED LOOPS (cr=40 pr=0 pw=0 time=164 us)
    5 NESTED LOOPS (cr=30 pr=0 pw=0 time=117 us)
    5 TABLE ACCESS BY INDEX ROWID SUB_CON_CALL_OFF_TAB (cr=15 pr=0 pw=0 time=69 us)
    5 INDEX UNIQUE SCAN SUB_CON_CALL_OFF_PK (cr=10 pr=0 pw=0 time=41 us)(object id 59706)
    5 TABLE ACCESS BY INDEX ROWID SUB_CONTRACT_TAB (cr=15 pr=0 pw=0 time=42 us)
    5 INDEX UNIQUE SCAN SUB_CONTRACT_PK (cr=10 pr=0 pw=0 time=26 us)(object id 59666)
    5 INDEX UNIQUE SCAN USER_PROFILE_ENTRY_SYS_PK (cr=10 pr=0 pw=0 time=41 us)(object id 60891)
    5 INDEX UNIQUE SCAN USER_ALLOWED_SITE_PK (cr=10 pr=0 pw=0 time=36 us)(object id 60866)
    5 FAST DUAL (cr=0 pr=0 pw=0 time=4 us)
    The issues raised by other posters are probably more important but I am wondering why the reference to FAST DUAL and other objects in the plan. There is no reference to these in the SQL. Is SUB_CON_CALL_OFF a view? If so can you post the view?

    BTW, it if SUB_CON_CALL_OFF is a view it is a good idea to put an identifier like "_vw" in the view name to understand at a glance that a view is being used
  • 7. Re: Query performance slow WHY
    VijayaraghavanKrishnan Pro
    Currently Being Moderated
    Hi Mark,

    Thanks for the metalink note and I have got the a doubt here

    Rows     Row Source Operation
    -------  ---------------------------------------------------
          5  FILTER  (cr=50 pr=0 pw=0 time=239 us)                         ---------------- Line 1
          5   NESTED LOOPS  (cr=40 pr=0 pw=0 time=164 us)            ---------------- Line 2
          5    NESTED LOOPS  (cr=30 pr=0 pw=0 time=117 us)           ---------------- Line 3
          5     TABLE ACCESS BY INDEX ROWID SUB_CON_CALL_OFF_TAB (cr=15 pr=0 pw=0 time=69 us)                            ---------------- Line 4
          5      INDEX UNIQUE SCAN SUB_CON_CALL_OFF_PK (cr=10 pr=0 pw=0 time=41 us)(object id 59706)                      ---------------- Line 5
          5     TABLE ACCESS BY INDEX ROWID SUB_CONTRACT_TAB (cr=15 pr=0 pw=0 time=42 us)                                  ---------------- Line 6
          5      INDEX UNIQUE SCAN SUB_CONTRACT_PK (cr=10 pr=0 pw=0 time=26 us)(object id 59666)                            ---------------- Line 7
          5    INDEX UNIQUE SCAN USER_PROFILE_ENTRY_SYS_PK (cr=10 pr=0 pw=0 time=41 us)(object id 60891)              ---------------- Line 8
          5   INDEX UNIQUE SCAN USER_ALLOWED_SITE_PK (cr=10 pr=0 pw=0 time=36 us)(object id 60866)                      ---------------- Line 9
          5    FAST DUAL  (cr=0 pr=0 pw=0 time=4 us)
     
    According the Metalink The time is the cumulative elapsed time for each step and the steps preceded it. Please let me know my understanding is right. The first line will hold the entire time taken to execute the SQL.

    When I go through this Row Source Plan, The line 7 should have the time more than 41 right? as it is the cumulative time from the preceding line right? Please correct me if my understanding is wrong.

    Thanks,
    Vijay

    Edited by: Vijayaraghavan Krishnan on Feb 4, 2013 11:23 AM
  • 8. Re: Query performance slow WHY
    Osama_Mustafa Oracle ACE
    Currently Being Moderated
    hi Ranit also its check the below link
    http://geekexplains.blogspot.com/2008/05/oracle-database-how-to-tune-for-better.html
  • 9. Re: Query performance slow WHY
    Mark D Powell Guru
    Currently Being Moderated
    No. Line 7 is an index unique scan which is used to access the table rows. There is no operation under line 7 for it to get time from. The result from the table row is feed back along with result of the previous index table access as part of a nested loop. You have to look to see which operation feeds (gets rows) from. Each step feeds its parent.

    HTH -- Mark D Powell --
  • 10. Re: Query performance slow WHY
    VijayaraghavanKrishnan Pro
    Currently Being Moderated
    Thanks Mark now I got it.

    Thanks,
    Vijay

Legend

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