This discussion is archived
1 2 Previous Next 20 Replies Latest reply: Feb 21, 2013 9:10 AM by 990849 RSS

Query runs much slower the second time!

669711 Newbie
Currently Being Moderated
I am doing a simple SELECT on a fairly complex view:
select * from balances where day = date'2011-08-15';
The results are correct, and they arrive in about 3 seconds. However, immediately repeating the exact same query takes about 3 minutes!

Using a different SELECT list and/or WHERE clause gives a quick result, but only once; repeating any past query triggers the big slowdown.

Doing ANALYZE TABLE on any of the tables involved in the view seems to reset things and the queries become fast again, but still only once for each specific query.

This view worked fine on 9i and has only started doing this since we moved to 11g.

Weird, eh?
  • 1. Re: Query runs much slower the second time!
    sb92075 Guru
    Currently Being Moderated
    user10587667 wrote:
    I am doing a simple SELECT on a fairly complex view:
    select * from balances where day = date'2011-08-15';
    The results are correct, and they arrive in about 3 seconds. However, immediately repeating the exact same query takes about 3 minutes!

    Using a different SELECT list and/or WHERE clause gives a quick result, but only once; repeating any past query triggers the big slowdown.

    Doing ANALYZE TABLE on any of the tables involved in the view seems to reset things and the queries become fast again, but still only once for each specific query.

    This view worked fine on 9i and has only started doing this since we moved to 11g.

    Weird, eh?
    YES

    consider
    ALTER SESSION SET SQL_TRACE=TRUE;

    the resultant trace file will contain details where time is being spent
  • 2. Re: Query runs much slower the second time!
    sb92075 Guru
    Currently Being Moderated
    user10587667 wrote:
    I am doing a simple SELECT on a fairly complex view:
    select * from balances where day = date'2011-08-15';
    The results are correct, and they arrive in about 3 seconds. However, immediately repeating the exact same query takes about 3 minutes!

    Using a different SELECT list and/or WHERE clause gives a quick result, but only once; repeating any past query triggers the big slowdown.

    Doing ANALYZE TABLE on any of the tables involved in the view seems to reset things and the queries become fast again, but still only once for each specific query.

    This view worked fine on 9i and has only started doing this since we moved to 11g.

    Weird, eh?
    YES

    consider
    ALTER SESSION SET SQL_TRACE=TRUE;

    the resultant trace file will contain details where time is being spent
  • 3. Re: Query runs much slower the second time!
    sb92075 Guru
    Currently Being Moderated
    user10587667 wrote:
    I am doing a simple SELECT on a fairly complex view:
    select * from balances where day = date'2011-08-15';
    The results are correct, and they arrive in about 3 seconds. However, immediately repeating the exact same query takes about 3 minutes!

    Using a different SELECT list and/or WHERE clause gives a quick result, but only once; repeating any past query triggers the big slowdown.

    Doing ANALYZE TABLE on any of the tables involved in the view seems to reset things and the queries become fast again, but still only once for each specific query.

    This view worked fine on 9i and has only started doing this since we moved to 11g.

    Weird, eh?
    YES

    consider
    ALTER SESSION SET SQL_TRACE=TRUE;

    the resultant trace file will contain details where time is being spent
  • 4. Re: Query runs much slower the second time!
    669711 Newbie
    Currently Being Moderated
    Okay, did that. It's pretty easy to see the difference. The first query:
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch      401      1.77       1.77          0     522592          0        5989
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      403      1.77       1.78          0     522592          0        5989
    And the second query:
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch      401    108.26     108.28          0   21189795          0        5989
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      403    108.27     108.29          0   21189795          0        5989
    About 40x more "query", which is "buffers gotten for consistent read".

    Which tells me... what exactly?
  • 5. Re: Query runs much slower the second time!
    sb92075 Guru
    Currently Being Moderated
    user10587667 wrote:
    Okay, did that. It's pretty easy to see the difference. The first query:
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch      401      1.77       1.77          0     522592          0        5989
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      403      1.77       1.78          0     522592          0        5989
    And the second query:
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch      401    108.26     108.28          0   21189795          0        5989
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      403    108.27     108.29          0   21189795          0        5989
    About 40x more "query", which is "buffers gotten for consistent read".

    Which tells me... what exactly?
    It quantifies that things are different.
    I'd like to see both EXPLAIN PLAN.

    What would "very" interesting would be the actual content of the long running trace file.

    We are both surprised at the current results & are looking to understand why the difference exists.
  • 6. Re: Query runs much slower the second time!
    669711 Newbie
    Currently Being Moderated
    Here's EXPLAIN PLAN, which is the same before the fast query, before the slow query, and after the slow query.
    -------------------------------------------------------------------------------------------------------------------
    | Id  | Operation                         | Name                  | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                  |                       |   184K|    11M|       |   364K  (1)| 01:12:52 |
    |   1 |  HASH GROUP BY                    |                       |   184K|    11M|    13M|   364K  (1)| 01:12:52 |
    |*  2 |   FILTER                          |                       |       |       |       |            |          |
    |   3 |    NESTED LOOPS OUTER             |                       |   184K|    11M|       |   361K  (1)| 01:12:17 |
    |   4 |     NESTED LOOPS                  |                       |  3071 | 82917 |       |    27   (0)| 00:00:01 |
    |   5 |      TABLE ACCESS BY INDEX ROWID  | GL_DAYS               |     1 |    12 |       |     2   (0)| 00:00:01 |
    |*  6 |       INDEX UNIQUE SCAN           | GL_DAYS_DAY           |     1 |       |       |     1   (0)| 00:00:01 |
    |*  7 |      TABLE ACCESS FULL            | GL_ACCOUNTS           |  3071 | 46065 |       |    25   (0)| 00:00:01 |
    |   8 |     VIEW                          |                       |    60 |  2340 |       |   118   (0)| 00:00:02 |
    |*  9 |      FILTER                       |                       |       |       |       |            |          |
    |* 10 |       TABLE ACCESS BY INDEX ROWID | GL_ENTRIES            |    60 |  1380 |       |    28   (0)| 00:00:01 |
    |* 11 |        INDEX RANGE SCAN           | GL_ENTRIES_BY_ACCOUNT |    46 |       |       |     2   (0)| 00:00:01 |
    |  12 |       NESTED LOOPS                |                       |     1 |    15 |       |     3   (0)| 00:00:01 |
    |  13 |        TABLE ACCESS BY INDEX ROWID| GL_VOUCHERS           |     1 |     7 |       |     2   (0)| 00:00:01 |
    |* 14 |         INDEX UNIQUE SCAN         | GL_VOUCHERS_PK        |     1 |       |       |     1   (0)| 00:00:01 |
    |* 15 |        TABLE ACCESS BY INDEX ROWID| GL_PERIODS            |   104 |   832 |       |     1   (0)| 00:00:01 |
    |* 16 |         INDEX UNIQUE SCAN         | GL_PERIODS_PK         |     1 |       |       |     0   (0)| 00:00:01 |
    -------------------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - filter(TO_DATE(' 2011-08-15 00:00:00', 'syyyy-mm-dd hh24:mi:ss')<CURRENT_DATE+730)
       6 - access("D"."DAY"=TO_DATE(' 2011-08-15 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))
           filter("D"."DAY"<CURRENT_DATE+730)
       7 - filter("A"."HAS_SUB"=0)
       9 - filter("D"."FISCAL_YEAR"= (SELECT "P"."FISCAL_YEAR" FROM MFA4."GL_PERIODS" "P",MFA4."GL_VOUCHERS"
                  "V" WHERE "V"."ID"=:B1 AND "P"."ID"="V"."PERIOD_ID" AND "P"."PERIOD_NO"<13))
      10 - filter("E"."ENTRY_DATE"<="D"."DAY")
      11 - access("E"."ACCOUNT_ID"="A"."ID")
      14 - access("V"."ID"=:B1)
      15 - filter("P"."PERIOD_NO"<13)
      16 - access("P"."ID"="V"."PERIOD_ID")
    As for the trace file, did you want the raw .trc file or the tkprof output?
  • 7. Re: Query runs much slower the second time!
    Paulie Pro
    Currently Being Moderated
    >
    |* 7 | TABLE ACCESS FULL | GL_ACCOUNTS | 3071 | 46065 | | 25 (0)| 00:00:01 |
    Why full access on a GL_Accounts table (which I'm guessing is large)?

    Can we have the table and view definitions also please?

    As for the trace file, did you want the raw .trc file or the tkprof output?
    I'd say tkprof in the first instance.


    Paul...
  • 8. Re: Query runs much slower the second time!
    Tubby Guru
    Currently Being Moderated
    user10587667 wrote:
    "V" WHERE "V"."ID"=:B1 AND "P"."ID"="V"."PERIOD_ID" AND "P"."PERIOD_NO"<13))
    Where is this bind variable coming from (:B1 above)? Your original query has a single predicate and it's a date (i'm assuming this is a number based on it's name).

    Do you have VPD on these tables generating dynamic predicates or anything 'funky' like that? What's the view definition look like?
  • 9. Re: Query runs much slower the second time!
    Dom Brooks Guru
    Currently Being Moderated
    I presume that execution plan is from EXPLAIN PLAN and not the actual execution plan/s at runtime.


    First impression is that it sounds like the effects of cardinality feedback.


    Can you check V$SQL and V$SQL_SHARED_CURSOR for child cursors / reasons for child cursors?
    See V$SQL_SHARED_CURSOR.USE_FEEDBACK_STATS for cardinality feedback indicator and also notes section in runtime execution plan.

    If there are different child cursors, please get the execution plans + predicate section + note section via DBMS_XPLAN.DISPLAY_CURSOR specifying the sql_id and the child numbers, e.g.
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(<sql_id>,<child#>,'ALLSTATS LAST'));
  • 10. Re: Query runs much slower the second time!
    669711 Newbie
    Currently Being Moderated
    I've created an index that seems to solve the problem. Thanks for your help folks -- I've learned a thing or two from you!
  • 11. Re: Query runs much slower the second time!
    Paulie Pro
    Currently Being Moderated
    >
    I've created an index that seems to solve the problem.
    Since you're replying to me, I assume that I was correct - just how large is the
    GL_Accounts table anyway?

    And even so, we still don't really have an explanation* of what was happening.
    Thanks for your
    help folks -- I've learned a thing or two from you!
    Well, if you decide to close the thread, give me a couple of points if I helped you.


    Paul...
  • 12. Re: Query runs much slower the second time!
    Paulie Pro
    Currently Being Moderated
    >
    I've created an index that seems to solve the problem.
    Since you're replying to me, I assume that I was correct - just how large is the
    GL_Accounts table anyway?

    And even so, we still don't really have an explanation* of what was happening.
    Thanks for your
    help folks -- I've learned a thing or two from you!
    Well, if you decide to mark this thread as answered, give me a couple of points if I helped you. ;)


    Paul...
  • 13. Re: Query runs much slower the second time!
    669711 Newbie
    Currently Being Moderated
    Okay, I marked it helpful.

    The GL_ACCOUNTS table has about 6,000 rows.
  • 14. Re: Query runs much slower the second time!
    669711 Newbie
    Currently Being Moderated
    Okay, I marked it helpful.

    The GL_ACCOUNTS table has about 6,000 rows.
1 2 Previous Next

Legend

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