This discussion is archived
1 2 3 Previous Next 32 Replies Latest reply: Aug 26, 2010 2:40 AM by NM Go to original post RSS
  • 15. Re: Query Takes more Time when i execute from the Instant client.
    NM Newbie
    Currently Being Moderated
    Hi Charles,

    Since morning i am running the same Queries(Client and Server side) what we did yesterday but not able see the produce the problem.

    The Time taken on Client and server side is almost same.Kindly suggest does the below view can be tuned.

    In the below Table tibex_order it will contain around 10million records.
     SELECT  LastInstUserAlias, max(LastInstMessageSequence)
                FROM  tibex_order
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
    select  mod(lastinstmessagesequence, 1000000000) LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias='2221';
    This is the View which is called.
    
    
    CREATE OR REPLACE VIEW TIBEX_MSGSEQBYUSERALIAS
    (USERALIAS, LASTINSTMESSAGESEQUENCE)
    AS 
    SELECT  userAlias, DECODE(NVL(max(LastInstMessageSequence), 0),-1,0,NVL(max(LastInstMessageSequence),0)) as LastInstMessageSequence
        FROM  (SELECT  LastInstUserAlias as UserAlias,
                      max(LastInstMessageSequence) as LastInstMessageSequence
                FROM  tibex_quote
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
              UNION ALL
              SELECT  LastInstUserAlias, max(LastInstMessageSequence)
                FROM  tibex_order
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
              UNION ALL
              SELECT  LastInstUserAlias, max(LastInstMessageSequence)
                FROM  tibex_TsTrade
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
              UNION ALL
              SELECT  LastInstUserAlias, max(LastInstMessageSequence)
                FROM  tibex_IOIRequest
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
              UNION ALL
              SELECT  LastInstUserAlias, max(LastInstMessageSequence)
                FROM  tibex_BestExRel
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
    -- BUGZID:17352 Remove EDPBookEntry table and views
    /*
              UNION ALL
              SELECT LastInstUserAlias, max(LastInstMessageSequence)
                FROM tibex_EDPBOOKENTRYVIEW
                WHERE LastInstUserAlias IS NOT NULL
                GROUP BY LastInstUserAlias
     */
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_INSTRUMENTADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_EDPPullOrders
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_PARTICIPANTADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_BESTEXRELATIONSADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_BOARDADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_DELETEADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_EXCHANGERATEADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_HYBRIDMMINSTRADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_MARKETADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_MMBBOLISTADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
    --          SELECT UserAlias, max(MessageSequence)
    --            FROM tibex_MMINSTRUMENTLISTADMIN
    --            WHERE UserAlias IS NOT NULL
    --            GROUP BY UserAlias
    --          UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_PARTCLRACCTMAPADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_SERVERADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_QUOTEADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_USERADMIN
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_cancelTrdAdmin
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              UNION ALL -- BUGZID:14129
              SELECT UserAlias, max(MessageSequence)
                FROM tibex_bulkCancelAdmin
                WHERE UserAlias IS NOT NULL
                GROUP BY UserAlias
              )
        GROUP BY userAlias
    /
    Regards
    NM
  • 16. Re: Query Takes more Time when i execute from the Instant client.
    CharlesHooper Expert
    Currently Being Moderated
    NM wrote:
    Hi Charles,

    I collected awr stats during that period.
    That was a good idea. However, an AWR report (and a Statspack report) is instance-wide, while you have already identified a specific session or connection characteristic that is experiencing a problem. Since that is the case, it is a better idea to use a more focused approach so that we are not mislead by statistics that are accumulated by unrelated sessions. The next step is a 10046 trace at level 8 or 12 that is specific to a particular session that is experiencing the problem, and a comparison of a 10046 trace at level 8 or 12 with a session that is not experiencing the performance problem.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 17. Re: Query Takes more Time when i execute from the Instant client.
    CharlesHooper Expert
    Currently Being Moderated
    NM wrote:
    Hi Charles,

    Since morning i am running the same Queries(Client and Server side) what we did yesterday but not able see the produce the problem.

    The Time taken on Client and server side is almost same.Kindly suggest does the below view can be tuned.

    In the below Table tibex_order it will contain around 10million records.
    (snip)
    Regards
    NM
    I did not spent much time looking at your view definition. This is another case where we are able to use the actual DBMS_XPLAN output that was generated earlier:
    Predicate Information (identified by operation id):
    ---------------------------------------------------
       5 - filter("LASTINSTUSERALIAS"=:SYS_B_1)
       8 - access("LASTINSTUSERALIAS"=:SYS_B_1)
      10 - filter(("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"=:SYS_B_1))
      12 - filter(("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"=:SYS_B_1))
      14 - filter(("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"=:SYS_B_1))
      16 - filter("USERALIAS"=:SYS_B_1)
      18 - filter("USERALIAS"=:SYS_B_1)
      20 - access("USERALIAS"=:SYS_B_1)
      22 - access("USERALIAS"=:SYS_B_1)
      24 - access("USERALIAS"=:SYS_B_1)
      26 - filter(("USERALIAS" IS NOT NULL AND "USERALIAS"=:SYS_B_1))
      28 - access("USERALIAS"=:SYS_B_1)
      30 - access("USERALIAS"=:SYS_B_1)
      32 - access("USERALIAS"=:SYS_B_1)
      34 - access("USERALIAS"=:SYS_B_1)
      36 - access("USERALIAS"=:SYS_B_1)
      38 - access("USERALIAS"=:SYS_B_1)
      40 - access("USERALIAS"=:SYS_B_1)
      42 - access("USERALIAS"=:SYS_B_1)
      44 - filter("USERALIAS"=:SYS_B_1)
      46 - filter("USERALIAS"=:SYS_B_1)
    In most cases above, "access" probably indicates an index type access, while "filter" probably indicates a full table scan type access. Taking another look at the execution plan:
    |   4 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.09 |    5512 |
    |*  5 |      TABLE ACCESS FULL          | TIBEX_QUOTE           |      1 |  21056 |      0 |00:00:00.09 |    5512 |
    |   6 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       4 |
    Plan ID 5 shows the table name and indicates a full table scan, and the number of rows returned are being reduced by "filter("LASTINSTUSERALIAS"=:SYS_B_1)" based on the predicate information section of the execution plan. Notice that it is looking for a specific LASTINSTUSERALIAS value. If there are many different distinct values in the LASTINSTUSERALIAS column (maybe more than 10 distinct values, with a roughly even number of rows with each value), it might make sense to consider indexing that column. Keep in mind that every index added must be maintained when rows are inserted, updated, or deleted in the table - and that will likely slow down day to day processing if you index too many columns.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 18. Re: Query Takes more Time when i execute from the Instant client.
    NM Newbie
    Currently Being Moderated
    Hi Charles,

    One my collegue was running the same query from instant client and below is the output.
    $ sqlplus trd_trd_ro/trd_trd_ro@prdba001/TRADE1
    
    SQL*Plus: Release 10.2.0.4.0 - Production on Tue Aug 10 17:49:51 2010
    
    Copyright (c) 1982, 2007, Oracle.  All Rights Reserved.
    
    
    Connected to:
    Oracle Database 10g Release 10.2.0.4.0 - Production
    
    SQL> set autotrace on explain statistics
    SQL> set timing on
    SQL> select mod(lastinstmessagesequence, 1000000000) LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias='2221';
    
    no rows selected
    
    Elapsed: 00:04:21.74
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 1955857846
    
    --------------------------------------------------------------------------------
    -------------------------
    
    | Id  | Operation                       | Name                  | Rows  | Bytes
    | Cost (%CPU)| Time     |
    
    --------------------------------------------------------------------------------
    -------------------------
    
    |   0 | SELECT STATEMENT                |                       |    21 |   399
    |  2548   (1)| 00:00:31 |
    
    |   1 |  SORT GROUP BY NOSORT           |                       |    21 |   399
    |  2548   (1)| 00:00:31 |
    
    |   2 |   VIEW                          |                       |    21 |   399
    |  2548   (1)| 00:00:31 |
    
    |   3 |    UNION-ALL                    |                       |       |
    |            |          |
    
    |   4 |     SORT GROUP BY NOSORT        |                       |     1 |    17
    |  1874   (1)| 00:00:23 |
    
    |*  5 |      TABLE ACCESS FULL          | TIBEX_QUOTE           | 21056 |   349K
    |  1874   (1)| 00:00:23 |
    
    |   6 |     SORT GROUP BY NOSORT        |                       |     1 |    17
    |   390   (0)| 00:00:05 |
    
    |   7 |      TABLE ACCESS BY INDEX ROWID| TIBEX_ORDER           |   660 | 11220
    |   390   (0)| 00:00:05 |
    
    |*  8 |       INDEX RANGE SCAN          | TIBEX_ORDER_IDX_OLT   |   660 |
    |    10   (0)| 00:00:01 |
    
    |   9 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |* 10 |      TABLE ACCESS FULL          | TIBEX_TSTRADE         |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |  11 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |* 12 |      TABLE ACCESS FULL          | TIBEX_IOIREQUEST      |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |  13 |     SORT GROUP BY NOSORT        |                       |     1 |    13
    |    35   (0)| 00:00:01 |
    
    |* 14 |      TABLE ACCESS FULL          | TIBEX_BESTEXREL       |     1 |    13
    |    35   (0)| 00:00:01 |
    
    |  15 |     SORT GROUP BY NOSORT        |                       |     1 |    17
    |   229   (1)| 00:00:03 |
    
    |* 16 |      INDEX FAST FULL SCAN       | SYS_C0058325          |   339 |  5763
    |   229   (1)| 00:00:03 |
    
    |  17 |     SORT GROUP BY NOSORT        |                       |     1 |    17
    |     9   (0)| 00:00:01 |
    
    |* 18 |      TABLE ACCESS FULL          | TIBEX_EDPPULLORDERS   |     1 |    17
    |     9   (0)| 00:00:01 |
    
    |  19 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 20 |      INDEX RANGE SCAN           | SYS_C0058803          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  21 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 22 |      INDEX RANGE SCAN           | SYS_C0057785          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  23 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 24 |      INDEX RANGE SCAN           | SYS_C0057827          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  25 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |* 26 |      TABLE ACCESS FULL          | TIBEX_DELETEADMIN     |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |  27 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 28 |      INDEX RANGE SCAN           | SYS_C0058148          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  29 |     SORT GROUP BY NOSORT        |                       |     1 |    15
    |     1   (0)| 00:00:01 |
    
    |* 30 |      INDEX RANGE SCAN           | SYS_C0058264          |     1 |    15
    |     1   (0)| 00:00:01 |
    
    |  31 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 32 |      INDEX RANGE SCAN           | SYS_C0058516          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  33 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 34 |      INDEX RANGE SCAN           | SYS_C0058561          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  35 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 36 |      INDEX RANGE SCAN           | SYS_C0058783          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  37 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 38 |      INDEX RANGE SCAN           | SYS_C0058977          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  39 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 40 |      INDEX RANGE SCAN           | SYS_C0058859          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  41 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |* 42 |      INDEX RANGE SCAN           | SYS_C0059197          |     1 |    19
    |     0   (0)| 00:00:01 |
    
    |  43 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |* 44 |      TABLE ACCESS FULL          | TIBEX_CANCELTRDADMIN  |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |  45 |     SORT GROUP BY NOSORT        |                       |     1 |    19
    |     2   (0)| 00:00:01 |
    
    |* 46 |      TABLE ACCESS FULL          | TIBEX_BULKCANCELADMIN |     1 |    19
    |     2   (0)| 00:00:01 |
    
    --------------------------------------------------------------------------------
    -------------------------
    
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       5 - filter("LASTINSTUSERALIAS"='2221')
       8 - access("LASTINSTUSERALIAS"='2221')
      10 - filter("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"='2221')
      12 - filter("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"='2221')
      14 - filter("LASTINSTUSERALIAS" IS NOT NULL AND "LASTINSTUSERALIAS"='2221')
      16 - filter("USERALIAS"='2221')
      18 - filter("USERALIAS"='2221')
      20 - access("USERALIAS"='2221')
      22 - access("USERALIAS"='2221')
      24 - access("USERALIAS"='2221')
      26 - filter("USERALIAS" IS NOT NULL AND "USERALIAS"='2221')
      28 - access("USERALIAS"='2221')
      30 - access("USERALIAS"='2221')
      32 - access("USERALIAS"='2221')
      34 - access("USERALIAS"='2221')
      36 - access("USERALIAS"='2221')
      38 - access("USERALIAS"='2221')
      40 - access("USERALIAS"='2221')
      42 - access("USERALIAS"='2221')
      44 - filter("USERALIAS"='2221')
      46 - filter("USERALIAS"='2221')
    
    
    Statistics
    ----------------------------------------------------------
              0  recursive calls
              0  db block gets
         440966  consistent gets
         407813  physical reads
              0  redo size
            332  bytes sent via SQL*Net to client
            481  bytes received via SQL*Net from client
              1  SQL*Net roundtrips to/from client
              0  sorts (memory)
              0  sorts (disk)
              0  rows processed
  • 19. Re: Query Takes more Time when i execute from the Instant client.
    Mohamed ELAzab Pro
    Currently Being Moderated
    Hello NM,
    I noticed that this table is being acessed full does this table have index on it?
    |* 5 | TABLE ACCESS FULL | TIBEX_QUOTE | 21056 | 349K
    Also i asked you to investigate the pga_aggregrate_target because all the sort operations is being done in that area becuase you have alot of sorts.
    also you need to generate awr in that period for the snapshot to invistigate the wait operations.
    kind regards
    Mohamed
    Oracle DBA
  • 20. Re: Query Takes more Time when i execute from the Instant client.
    NM Newbie
    Currently Being Moderated
    Hi Mohamed,

    I execute this Query nearly 200 times today and it used to come out in 12 milliseconds.But when they do from Instant client some times this problem exist and Immediately cancel the query and rerun the Query then it will come out 10 milliseconds.
    Top 5 Timed Events                                         Avg %Total
    ~~~~~~~~~~~~~~~~~~                                        wait   Call
    Event                                 Waits    Time (s)   (ms)   Time Wait Class
    ------------------------------ ------------ ----------- ------ ------ ----------
    db file scattered read              659,124       2,483      4   50.3   User I/O
    CPU time                                          1,161          23.5
    log file parallel write             622,780         685      1   13.9 System I/O
    read by other session               169,449         646      4   13.1   User I/O
    db file sequential read              48,017         469     10    9.5   User I/O
    
    Statistic Name                                       Time (s) % of DB Time
    ------------------------------------------ ------------------ ------------
    sql execute elapsed time                              4,716.8         95.5
    DB CPU                                                1,161.0         23.5
    connection management call elapsed time                  10.1           .2
    parse time elapsed                                        5.0           .1
    hard parse elapsed time                                   3.6           .1
    PL/SQL execution elapsed time                             1.2           .0
    PL/SQL compilation elapsed time                           0.5           .0
    hard parse (sharing criteria) elapsed time                0.4           .0
    hard parse (bind mismatch) elapsed time                   0.2           .0
    failed parse elapsed time                                 0.0           .0
    repeated bind elapsed time                                0.0           .0
    sequence load elapsed time                                0.0           .0
    DB time                                               4,938.9          N/A
    background elapsed time                               1,203.0          N/A
    background cpu time                                     434.7          N/A
              -------------------------------------------------------------
    Wait Class                      Waits  -outs         Time (s)    (ms)      /txn
    -------------------- ---------------- ------ ---------------- ------- ---------
    User I/O                      891,573     .0            3,929       4       0.8
    System I/O                    686,914     .0              995       1       0.6
    Concurrency                    77,497     .0               52       1       0.1
    Commit                          2,086     .6                7       4       0.0
    Network                     4,038,197     .0                6       0       3.4
    Configuration                  36,077   99.0                3       0       0.0
    Other                          31,441    8.8                2       0       0.0
    Application                        21     .0                0       1       0.0
              -------------------------------------------------------------
    -> ordered by wait time desc, waits desc (idle events last)
    
                                                                       Avg
                                                 %Time  Total Wait    wait     Waits
    Event                                 Waits  -outs    Time (s)    (ms)      /txn
    ---------------------------- -------------- ------ ----------- ------- ---------
    db file scattered read              659,124     .0       2,483       4       0.6
    log file parallel write             622,780     .0         685       1       0.5
    read by other session               169,449     .0         646       4       0.1
    db file sequential read              48,017     .0         469      10       0.0
    db file parallel write               59,275     .0         302       5       0.1
    direct path write temp                6,789     .0         277      41       0.0
    direct path read temp                 8,056     .0          54       7       0.0
    enq: TX - index contention            8,565     .0          46       5       0.0
    log file sync                         2,086     .6           7       4       0.0
    SQL*Net message to client         4,027,220     .0           6       0       3.4
    
    
           444         48            8       55.4     9.0 03fqwamsdv6pf
    Module: perbroker@prdba001 (TNS V1-V3)
    select mod(lastinstmessagesequence, :"SYS_B_0") LastInstIDSeqNo from tibex_msgse
    qbyuseralias where useralias=:"SYS_B_1"
  • 21. Re: Query Takes more Time when i execute from the Instant client.
    sb92075 Guru
    Currently Being Moderated
    But when they do from Instant client some times this problem exist
    Perhaps you should consider not using Instant Client; which does not ship with V11 Oracle.
    It apparently caused more problems than it solved for Oracle.
  • 22. Re: Query Takes more Time when i execute from the Instant client.
    Randolf Geist Oracle ACE Director
    Currently Being Moderated
    NM wrote:
    Hi Charles,

    One my collegue was running the same query from instant client and below is the output.
    SQL> set autotrace on explain statistics
    SQL> set timing on
    SQL> select mod(lastinstmessagesequence, 1000000000) LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias='2221';
    
    no rows selected
    
    Elapsed: 00:04:21.74
    ...(snip)
    As already pointed out by Charles using AUTOTRACE / EXPLAIN features are probably not going to be helpful in your particular case since these tools can lie regarding the reported execution plans.

    There are several options how you can try to tackle this:

    1. If you are able to reproduce the issue at will then tracing the session with extended trace as suggested by Charles should allow you to understand why the execution is slow when analyzing the generated trace file with a trace analyzer like TKPROF

    However at present it looks like you can't reproduce it at will, so here are other options that you can use to extract information from historic data captured by AWR / ASH

    2. Since you seem to have an AWR license you could try to see what execution plans for your statements have been captured by AWR by using DBMS_XPLAN.DISPLAY_AWR, may be you're lucky and you can identify different execution plans for your particular SQL_ID, and if there are execution plans with PLAN_HASH_VALUEs unequal 1955857846 then one of these might be the one causing the problems (assuming that the issue is caused by different execution plans).

    You could also try to generate an AWR SQL report for your particular SQL_ID using the $ORACLE_HOME/rdbms/admin/awrsqrpt.sql script for more details that have been captured about this particular SQL_ID.

    3. You can also try to gather more detailed information about the statement executions by using the ASH report limited to this particular SQL_ID. If you know approximately the period when a slow execution took place, then follow the instructions in the header of the $ORACLE_HOME/rdbms/admin/ashrpt.sql script how to setup the defines for running the $ORACLE_HOME/rdbms/admin/ashrpti.sql script for a particular SQL_ID. The report will tell you what has been captured in the Active Session History for this particular SQL_ID during the specified period. This might help you again to understand where the majority of the time has been spent. Unfortunately in 10.2 the information about the SQL_PLAN_LINE_ID is not available from V$ACTIVE_SESSION_HISTORY, this has been added in 11.1 and is very helpful in identifying which parts of the execution plan took most of the time.

    If above doesn't help here is what you can do if you encounter such a slow statement execution. Note that this is probably only helpful if you can perform these actions while this slow execution takes place:

    4. While the slow execution is running, try to capture the particular execution plan from the shared pool by using DBMS_XPLAN.DISPLAY_CURSOR with the SQL_ID and SQL_CHILD_NUMBER taken from V$SESSION of the session executing the slow query to identify the actual plan used for execution and to see if it is different from the execution plan with the PLAN_HASH_VALUE = 1955857846

    5. While the slow execution is running, use Tanel Poder's "snapper" utility (http://tech.e2sn.com/oracle-scripts-and-tools/session-snapper) to capture information of the session executing the slow query. This will give you an indication about the work that the session performs and the wait events encountered

    6. While the slow execution is running, use Tanel Poder's "os_explain"utility (http://blog.tanelpoder.com/2008/06/15/advanced-oracle-troubleshooting-guide-part-6-understanding-oracle-execution-plans-with-os_explain/) to capture information about the actual execution of the slow query. This will ultimately tell you what the process on the server side is doing

    Regards,
    Randolf

    Oracle related stuff blog:
    http://oracle-randolf.blogspot.com/

    Co-author of the "OakTable Expert Oracle Practices" book:
    http://www.apress.com/book/view/1430226684
    http://www.amazon.com/Expert-Oracle-Practices-Database-Administration/dp/1430226684
  • 23. Re: Query Takes more Time when i execute from the Instant client.
    Mohamed ELAzab Pro
    Currently Being Moderated
    Hello,
    i agree with sb.stop using that client because i think it has a problem with its driver.you can open SR with Oracle to ask more about if this client is supported.
    Kind regards
    Mohamed
  • 24. Re: Query Takes more Time when i execute from the Instant client.
    NM Newbie
    Currently Being Moderated
    Hi Charles,

    Today again this problem occurred.I Executed the Query on Server and output came in 11 milliseconds and same query executed from Instant Client and same problem exist and i did the trace as you guided.
    TKPROF: Release 10.2.0.4.0 - Production on Thu Aug 12 18:12:47 2010
    
    Copyright (c) 1982, 2007, Oracle.  All rights reserved.
    
    Trace file: trade1_ora_13517_10046.trc
    Sort options: default
    
    ********************************************************************************
    count    = number of times OCI procedure was executed
    cpu      = cpu time in seconds executing 
    elapsed  = elapsed time in seconds executing
    disk     = number of physical reads of buffers from disk
    query    = number of buffers gotten for consistent read
    current  = number of buffers gotten in current mode (usually for update)
    rows     = number of rows processed by the fetch or execute call
    ********************************************************************************
    
    select  mod(lastinstmessagesequence, :"SYS_B_0") LastInstIDSeqNo 
    from
     tibex_msgseqbyuseralias where useralias=:"SYS_B_1"
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.02       0.00          0          0          0           0
    Fetch        1     23.68     242.25     255454     493346          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3     23.70     242.26     255454     493346          0           0
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 97  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  SORT GROUP BY NOSORT (cr=493346 pr=255454 pw=0 time=242256982 us)
          0   VIEW  (cr=493346 pr=255454 pw=0 time=242256956 us)
          0    UNION-ALL  (cr=493346 pr=255454 pw=0 time=242256953 us)
          0     HASH GROUP BY (cr=9405 pr=0 pw=0 time=171791 us)
          0      TABLE ACCESS FULL TIBEX_QUOTE (cr=9405 pr=0 pw=0 time=171536 us)
          0     HASH GROUP BY (cr=480896 pr=255454 pw=0 time=242064507 us)
          0      TABLE ACCESS FULL TIBEX_ORDER (cr=480896 pr=255454 pw=0 time=242064378 us)
          0     HASH GROUP BY (cr=3 pr=0 pw=0 time=171 us)
          0      TABLE ACCESS FULL TIBEX_TSTRADE (cr=3 pr=0 pw=0 time=41 us)
          0     HASH GROUP BY (cr=3 pr=0 pw=0 time=56 us)
          0      TABLE ACCESS FULL TIBEX_IOIREQUEST (cr=3 pr=0 pw=0 time=12 us)
          0     HASH GROUP BY (cr=126 pr=0 pw=0 time=1139 us)
          0      TABLE ACCESS FULL TIBEX_BESTEXREL (cr=126 pr=0 pw=0 time=1096 us)
          0     HASH GROUP BY (cr=2862 pr=0 pw=0 time=18123 us)
          0      INDEX FAST FULL SCAN SYS_C0058325 (cr=2862 pr=0 pw=0 time=18042 us)(object id 101665)
          0     HASH GROUP BY (cr=31 pr=0 pw=0 time=808 us)
          0      TABLE ACCESS FULL TIBEX_EDPPULLORDERS (cr=31 pr=0 pw=0 time=746 us)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=27 us)
          0      INDEX FULL SCAN SYS_C0058803 (cr=1 pr=0 pw=0 time=21 us)(object id 101851)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)
          0      INDEX FULL SCAN SYS_C0057785 (cr=1 pr=0 pw=0 time=7 us)(object id 101398)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
          0      INDEX FULL SCAN SYS_C0057827 (cr=1 pr=0 pw=0 time=4 us)(object id 101406)
          0     HASH GROUP BY (cr=3 pr=0 pw=0 time=40 us)
          0      TABLE ACCESS FULL TIBEX_DELETEADMIN (cr=3 pr=0 pw=0 time=18 us)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)
          0      INDEX FULL SCAN SYS_C0058148 (cr=1 pr=0 pw=0 time=8 us)(object id 101576)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
          0      INDEX FULL SCAN SYS_C0058264 (cr=1 pr=0 pw=0 time=6 us)(object id 101642)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)
          0      INDEX FULL SCAN SYS_C0058516 (cr=1 pr=0 pw=0 time=6 us)(object id 101740)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
          0      INDEX FULL SCAN SYS_C0058561 (cr=1 pr=0 pw=0 time=4 us)(object id 101759)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
          0      INDEX FULL SCAN SYS_C0058783 (cr=1 pr=0 pw=0 time=6 us)(object id 101842)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)
          0      INDEX FULL SCAN SYS_C0058977 (cr=1 pr=0 pw=0 time=6 us)(object id 101947)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=11 us)
          0      INDEX FULL SCAN SYS_C0058859 (cr=1 pr=0 pw=0 time=6 us)(object id 101884)
          0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=13 us)
          0      INDEX FULL SCAN SYS_C0059197 (cr=1 pr=0 pw=0 time=8 us)(object id 102043)
          0     HASH GROUP BY (cr=3 pr=0 pw=0 time=35 us)
          0      TABLE ACCESS FULL TIBEX_CANCELTRDADMIN (cr=3 pr=0 pw=0 time=17 us)
          0     HASH GROUP BY (cr=3 pr=0 pw=0 time=33 us)
          0      TABLE ACCESS FULL TIBEX_BULKCANCELADMIN (cr=3 pr=0 pw=0 time=12 us)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      db file scattered read                      32286        0.12        166.99
      db file sequential read                       111        0.01          0.07
      read by other session                       55408        0.05         58.57
      SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************
    
    select text 
    from
     view$ where rowid=:1
    
    
    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        1      0.00       0.00          1          2          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.00          1          2          0           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: CHOOSE
    Parsing user id: SYS   (recursive depth: 1)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=1 pw=0 time=3404 us)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
      db file sequential read                         1        0.00          0.00
    ********************************************************************************
    
    select :"SYS_B_0" 
    from
     dual
    
    
    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        2      0.00       0.00          0          0          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.00       0.00          0          0          0           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 97  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  FAST DUAL  (cr=0 pr=0 pw=0 time=3 us)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       2        0.00          0.00
      SQL*Net message from client                     2        0.00          0.00
    ********************************************************************************
    
    ALTER session SET EVENTS '10046 trace name context off'
    
    
    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        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.00       0.00          0          0          0           0
    
    Misses in library cache during parse: 0
    Parsing user id: 97  
    
    
    
    ********************************************************************************
    
    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        3      0.00       0.00          0          0          0           0
    Execute      3      0.02       0.00          0          0          0           0
    Fetch        3     23.68     242.25     255454     493346          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        9     23.70     242.26     255454     493346          0           1
    
    Misses in library cache during parse: 2
    Misses in library cache during execute: 2
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       7        0.00          0.00
      SQL*Net message from client                     7       38.83         51.80
      db file sequential read                       111        0.01          0.07
      db file scattered read                      32286        0.12        166.99
      read by other session                       55408        0.05         58.57
    
    
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    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        1      0.00       0.00          1          2          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.00          1          2          0           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                         1        0.00          0.00
    
        3  user  SQL statements in session.
        1  internal SQL statements in session.
        4  SQL statements in session.
    ********************************************************************************
    Trace file: trade1_ora_13517_10046.trc
    Trace file compatibility: 10.01.00
    Sort options: default
    
           1  session in tracefile.
           3  user  SQL statements in trace file.
           1  internal SQL statements in trace file.
           4  SQL statements in trace file.
           4  unique SQL statements in trace file.
       87965  lines in trace file.
         255  elapsed seconds in trace file.
    
    
    Trace Files Details
    /u01/app/oracle/admin/TRADE1/udump/trade1_ora_13517_10046.trc
    Oracle Database 10g Release 10.2.0.4.0 - Production
    ORACLE_HOME = /u01/app/oracle/product/10.2.0/db
    System name:     SunOS
    Node name:     prdba001
    Release:     5.10
    Version:     Generic_139556-08
    Machine:     i86pc
    Instance name: TRADE1
    Redo thread mounted by this instance: 1
    Oracle process number: 99
    Unix process pid: 13517, image: oracle@prdba001
    
    *** 2010-08-12 18:07:19.558
    *** ACTION NAME:() 2010-08-12 18:07:19.558
    *** MODULE NAME:(SQL*Plus) 2010-08-12 18:07:19.558
    *** SERVICE NAME:(TRADE1) 2010-08-12 18:07:19.558
    *** SESSION ID:(215.16514) 2010-08-12 18:07:19.558
    WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9447469937543
    WAIT #2: nam='SQL*Net message from client' ela= 189 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9447469937865
    WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9447469937907
    *** 2010-08-12 18:07:59.324
    WAIT #0: nam='SQL*Net message from client' ela= 38832679 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9447508770609
    =====================
    PARSING IN CURSOR #3 len=120 dep=0 uid=97 oct=3 lid=99 tim=9447508771750 hv=204457666 ad='7cdadae8'
    select  mod(lastinstmessagesequence, :"SYS_B_0") LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias=:"SYS_B_1"
    END OF STMT
    PARSE #3:c=0,e=945,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=9447508771740
    =====================
    PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=9447508773393 hv=1398610540 ad='7ef48a18'
    select text from view$ where rowid=:1
    END OF STMT
    PARSE #2:c=0,e=1418,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=9447508773391
    BINDS #2:
    kkscoacd
     Bind#0
      oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
      oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
      kxsbbbfp=fffffd7ffdbb16e0  bln=16  avl=16  flg=05
      value=0000D27F.0000.0001
    EXEC #2:c=0,e=2098,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=9447508775550
    WAIT #2: nam='db file sequential read' ela= 3113 file#=1 block#=53887 blocks=1 obj#=63 tim=9447508778917
    FETCH #2:c=0,e=3425,p=1,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=9447508779000
    STAT #2 id=1 cnt=1 pid=0 pos=1 obj=63 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=1 pw=0 time=3404 us)'
    BINDS #3:
    kkscoacd
     Bind#0
      oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
      oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
      kxsbbbfp=fffffd7ffdbb2530  bln=22  avl=02  flg=09
      value=1000000000
     Bind#1
      oacdty=02 mxl=22(03) mxlc=00 mal=00 scl=00 pre=00
      oacflg=10 fl2=0300 frm=00 csi=00 siz=24 off=0
      kxsbbbfp=fffffd7ffdbb24e8  bln=22  avl=03  flg=09
      value=2228
    EXEC #3:c=20000,e=15877,p=1,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=9447508787670
    WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9447508787713
    WAIT #3: nam='db file scattered read' ela= 13221 file#=6 block#=214796 blocks=5 obj#=101804 tim=9447508972972
    WAIT #3: nam='db file scattered read' ela= 14568 file#=6 block#=905 blocks=8 obj#=101804 tim=9447508987786
    WAIT #3: nam='db file scattered read' ela= 32396 file#=6 block#=922 blocks=7 obj#=101804 tim=9447509020555
    WAIT #3: nam='read by other session' ela= 1772 file#=6 block#=890284 class#=1 obj#=101804 tim=9447683396281
    WAIT #3: nam='read by other session' ela= 2 file#=6 block#=890292 class#=1 obj#=101804 tim=9447683396555
    WAIT #3: nam='read by other session' ela= 1487 file#=6 block#=890292 class#=1 obj#=101804 tim=9447683398067
    WAIT #3: nam='read by other session' ela= 2 file#=6 block#=890300 class#=1 obj#=101804 tim=9447683398308
    WAIT #3: nam='read by other session' ela= 1528 file#=6 block#=890300 class#=1 obj#=101804 tim=9447683399849
    WAIT #3: nam='read by other session' ela= 4 file#=6 block#=890310 class#=1 obj#=101804 tim=9447683400173
    WAIT #3: nam='read by other session' ela= 1497 file#=6 block#=890310 class#=1 obj#=101804 tim=9447683401692
    WAIT #3: nam='read by other session' ela= 1 file#=6 block#=890318 class#=1 obj#=101804 tim=9447683401938
    WAIT #3: nam='read by other session' ela= 1368 file#=6 block#=890318 class#=1 obj#=101804 tim=9447683403318
    WAIT #3: nam='read by other session' ela= 1 file#=6 block#=890326 class#=1 obj#=101804 tim=9447683403562
    WAIT #3: nam='read by other session' ela= 2 file#=6 block#=1475577 class#=1 obj#=101804 tim=9447751022223
    WAIT #3: nam='read by other session' ela= 1289 file#=6 block#=1475577 class#=1 obj#=101804 tim=9447751023532
    FETCH #3:c=23680000,e=242256812,p=255454,cr=493346,cu=0,mis=0,r=0,dep=0,og=1,tim=9447751044552
    WAIT #3: nam='SQL*Net message from client' ela= 1200 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447751045930
    STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY NOSORT (cr=493346 pr=255454 pw=0 time=242256982 us)'
    STAT #3 id=2 cnt=0 pid=1 pos=1 obj=0 op='VIEW  (cr=493346 pr=255454 pw=0 time=242256956 us)'
    STAT #3 id=3 cnt=0 pid=2 pos=1 obj=0 op='UNION-ALL  (cr=493346 pr=255454 pw=0 time=242256953 us)'
    STAT #3 id=4 cnt=0 pid=3 pos=1 obj=0 op='HASH GROUP BY (cr=9405 pr=0 pw=0 time=171791 us)'
    STAT #3 id=5 cnt=0 pid=4 pos=1 obj=101876 op='TABLE ACCESS FULL TIBEX_QUOTE (cr=9405 pr=0 pw=0 time=171536 us)'
    STAT #3 id=6 cnt=0 pid=3 pos=2 obj=0 op='HASH GROUP BY (cr=480896 pr=255454 pw=0 time=242064507 us)'
    STAT #3 id=7 cnt=0 pid=6 pos=1 obj=101804 op='TABLE ACCESS FULL TIBEX_ORDER (cr=480896 pr=255454 pw=0 time=242064378 us)'
    STAT #3 id=8 cnt=0 pid=3 pos=3 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=171 us)'
    STAT #3 id=9 cnt=0 pid=8 pos=1 obj=102015 op='TABLE ACCESS FULL TIBEX_TSTRADE (cr=3 pr=0 pw=0 time=41 us)'
    STAT #3 id=10 cnt=0 pid=3 pos=4 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=56 us)'
    STAT #3 id=11 cnt=0 pid=10 pos=1 obj=101710 op='TABLE ACCESS FULL TIBEX_IOIREQUEST (cr=3 pr=0 pw=0 time=12 us)'
    STAT #3 id=12 cnt=0 pid=3 pos=5 obj=0 op='HASH GROUP BY (cr=126 pr=0 pw=0 time=1139 us)'
    STAT #3 id=13 cnt=0 pid=12 pos=1 obj=101395 op='TABLE ACCESS FULL TIBEX_BESTEXREL (cr=126 pr=0 pw=0 time=1096 us)'
    STAT #3 id=14 cnt=0 pid=3 pos=6 obj=0 op='HASH GROUP BY (cr=2862 pr=0 pw=0 time=18123 us)'
    STAT #3 id=15 cnt=0 pid=14 pos=1 obj=101665 op='INDEX FAST FULL SCAN SYS_C0058325 (cr=2862 pr=0 pw=0 time=18042 us)'
    STAT #3 id=16 cnt=0 pid=3 pos=7 obj=0 op='HASH GROUP BY (cr=31 pr=0 pw=0 time=808 us)'
    STAT #3 id=17 cnt=0 pid=16 pos=1 obj=407076 op='TABLE ACCESS FULL TIBEX_EDPPULLORDERS (cr=31 pr=0 pw=0 time=746 us)'
    STAT #3 id=18 cnt=0 pid=3 pos=8 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=27 us)'
    STAT #3 id=19 cnt=0 pid=18 pos=1 obj=101851 op='INDEX FULL SCAN SYS_C0058803 (cr=1 pr=0 pw=0 time=21 us)'
    STAT #3 id=20 cnt=0 pid=3 pos=9 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)'
    STAT #3 id=21 cnt=0 pid=20 pos=1 obj=101398 op='INDEX FULL SCAN SYS_C0057785 (cr=1 pr=0 pw=0 time=7 us)'
    STAT #3 id=22 cnt=0 pid=3 pos=10 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=23 cnt=0 pid=22 pos=1 obj=101406 op='INDEX FULL SCAN SYS_C0057827 (cr=1 pr=0 pw=0 time=4 us)'
    STAT #3 id=24 cnt=0 pid=3 pos=11 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=40 us)'
    STAT #3 id=25 cnt=0 pid=24 pos=1 obj=101497 op='TABLE ACCESS FULL TIBEX_DELETEADMIN (cr=3 pr=0 pw=0 time=18 us)'
    STAT #3 id=26 cnt=0 pid=3 pos=12 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)'
    STAT #3 id=27 cnt=0 pid=26 pos=1 obj=101576 op='INDEX FULL SCAN SYS_C0058148 (cr=1 pr=0 pw=0 time=8 us)'
    STAT #3 id=28 cnt=0 pid=3 pos=13 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=29 cnt=0 pid=28 pos=1 obj=101642 op='INDEX FULL SCAN SYS_C0058264 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=30 cnt=0 pid=3 pos=14 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)'
    STAT #3 id=31 cnt=0 pid=30 pos=1 obj=101740 op='INDEX FULL SCAN SYS_C0058516 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=32 cnt=0 pid=3 pos=15 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=33 cnt=0 pid=32 pos=1 obj=101759 op='INDEX FULL SCAN SYS_C0058561 (cr=1 pr=0 pw=0 time=4 us)'
    STAT #3 id=34 cnt=0 pid=3 pos=16 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=35 cnt=0 pid=34 pos=1 obj=101842 op='INDEX FULL SCAN SYS_C0058783 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=36 cnt=0 pid=3 pos=17 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)'
    STAT #3 id=37 cnt=0 pid=36 pos=1 obj=101947 op='INDEX FULL SCAN SYS_C0058977 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=38 cnt=0 pid=3 pos=18 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=11 us)'
    STAT #3 id=39 cnt=0 pid=38 pos=1 obj=101884 op='INDEX FULL SCAN SYS_C0058859 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=40 cnt=0 pid=3 pos=19 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=13 us)'
    STAT #3 id=41 cnt=0 pid=40 pos=1 obj=102043 op='INDEX FULL SCAN SYS_C0059197 (cr=1 pr=0 pw=0 time=8 us)'
    STAT #3 id=42 cnt=0 pid=3 pos=20 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=35 us)'
    STAT #3 id=43 cnt=0 pid=42 pos=1 obj=101423 op='TABLE ACCESS FULL TIBEX_CANCELTRDADMIN (cr=3 pr=0 pw=0 time=17 us)'
    STAT #3 id=44 cnt=0 pid=3 pos=21 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=33 us)'
    STAT #3 id=45 cnt=0 pid=44 pos=1 obj=186696 op='TABLE ACCESS FULL TIBEX_BULKCANCELADMIN (cr=3 pr=0 pw=0 time=12 us)'
    WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447751046529
    *** 2010-08-12 18:12:20.693
    WAIT #0: nam='SQL*Net message from client' ela= 12968305 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764014851
    =====================
    PARSING IN CURSOR #2 len=27 dep=0 uid=97 oct=3 lid=99 tim=9447764015323 hv=2057858921 ad='7d8b4498'
    select :"SYS_B_0" from dual
    END OF STMT
    PARSE #2:c=0,e=339,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=9447764015320
    BINDS #2:
    kkscoacd
     Bind#0
      oacdty=01 mxl=32(20) mxlc=00 mal=00 scl=00 pre=00
      oacflg=10 fl2=0100 frm=01 csi=31 siz=32 off=0
      kxsbbbfp=fffffd7ffdadefc0  bln=32  avl=20  flg=09
      value="verify cursor closed"
    EXEC #2:c=0,e=692,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=9447764016055
    WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764016088
    FETCH #2:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=9447764016124
    WAIT #2: nam='SQL*Net message from client' ela= 379 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764016576
    FETCH #2:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=9447764016608
    WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764016645
    WAIT #2: nam='SQL*Net message from client' ela= 350 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764017015
    STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=3 us)'
    WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764017100
    WAIT #0: nam='SQL*Net message from client' ela= 228 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447764017346
    =====================
    PARSING IN CURSOR #3 len=55 dep=0 uid=97 oct=42 lid=99 tim=9447764017477 hv=3096290290 ad='0'
    ALTER session SET EVENTS '10046 trace name context off'
    END OF STMT
    PARSE #3:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=9447764017475
    EXEC #3:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=9447764017573
  • 25. Re: Query Takes more Time when i execute from the Instant client.
    CharlesHooper Expert
    Currently Being Moderated
    NM wrote:
    Hi Charles,

    Today again this problem occurred.I Executed the Query on Server and output came in 11 milliseconds and same query executed from Instant Client and same problem exist and i did the trace as you guided.
    TKPROF: Release 10.2.0.4.0 - Production on Thu Aug 12 18:12:47 2010
    (snip)
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 97  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
    0  SORT GROUP BY NOSORT (cr=493346 pr=255454 pw=0 time=242256982 us)
    0   VIEW  (cr=493346 pr=255454 pw=0 time=242256956 us)
    0    UNION-ALL  (cr=493346 pr=255454 pw=0 time=242256953 us)
    0     HASH GROUP BY (cr=9405 pr=0 pw=0 time=171791 us)
    0      TABLE ACCESS FULL TIBEX_QUOTE (cr=9405 pr=0 pw=0 time=171536 us)
    0     HASH GROUP BY (cr=480896 pr=255454 pw=0 time=242064507 us)
    0      TABLE ACCESS FULL TIBEX_ORDER (cr=480896 pr=255454 pw=0 time=242064378 us)
    0     HASH GROUP BY (cr=3 pr=0 pw=0 time=171 us)
    0      TABLE ACCESS FULL TIBEX_TSTRADE (cr=3 pr=0 pw=0 time=41 us)
    0     HASH GROUP BY (cr=3 pr=0 pw=0 time=56 us)
    0      TABLE ACCESS FULL TIBEX_IOIREQUEST (cr=3 pr=0 pw=0 time=12 us)
    0     HASH GROUP BY (cr=126 pr=0 pw=0 time=1139 us)
    0      TABLE ACCESS FULL TIBEX_BESTEXREL (cr=126 pr=0 pw=0 time=1096 us)
    0     HASH GROUP BY (cr=2862 pr=0 pw=0 time=18123 us)
    0      INDEX FAST FULL SCAN SYS_C0058325 (cr=2862 pr=0 pw=0 time=18042 us)(object id 101665)
    0     HASH GROUP BY (cr=31 pr=0 pw=0 time=808 us)
    0      TABLE ACCESS FULL TIBEX_EDPPULLORDERS (cr=31 pr=0 pw=0 time=746 us)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=27 us)
    0      INDEX FULL SCAN SYS_C0058803 (cr=1 pr=0 pw=0 time=21 us)(object id 101851)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)
    0      INDEX FULL SCAN SYS_C0057785 (cr=1 pr=0 pw=0 time=7 us)(object id 101398)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    0      INDEX FULL SCAN SYS_C0057827 (cr=1 pr=0 pw=0 time=4 us)(object id 101406)
    0     HASH GROUP BY (cr=3 pr=0 pw=0 time=40 us)
    0      TABLE ACCESS FULL TIBEX_DELETEADMIN (cr=3 pr=0 pw=0 time=18 us)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)
    0      INDEX FULL SCAN SYS_C0058148 (cr=1 pr=0 pw=0 time=8 us)(object id 101576)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    0      INDEX FULL SCAN SYS_C0058264 (cr=1 pr=0 pw=0 time=6 us)(object id 101642)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)
    0      INDEX FULL SCAN SYS_C0058516 (cr=1 pr=0 pw=0 time=6 us)(object id 101740)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    0      INDEX FULL SCAN SYS_C0058561 (cr=1 pr=0 pw=0 time=4 us)(object id 101759)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    0      INDEX FULL SCAN SYS_C0058783 (cr=1 pr=0 pw=0 time=6 us)(object id 101842)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)
    0      INDEX FULL SCAN SYS_C0058977 (cr=1 pr=0 pw=0 time=6 us)(object id 101947)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=11 us)
    0      INDEX FULL SCAN SYS_C0058859 (cr=1 pr=0 pw=0 time=6 us)(object id 101884)
    0     SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=13 us)
    0      INDEX FULL SCAN SYS_C0059197 (cr=1 pr=0 pw=0 time=8 us)(object id 102043)
    0     HASH GROUP BY (cr=3 pr=0 pw=0 time=35 us)
    0      TABLE ACCESS FULL TIBEX_CANCELTRDADMIN (cr=3 pr=0 pw=0 time=17 us)
    0     HASH GROUP BY (cr=3 pr=0 pw=0 time=33 us)
    0      TABLE ACCESS FULL TIBEX_BULKCANCELADMIN (cr=3 pr=0 pw=0 time=12 us)
    
    
    Elapsed times include waiting on following events:
    Event waited on                             Times   Max. Wait  Total Waited
    ----------------------------------------   Waited  ----------  ------------
    SQL*Net message to client                       1        0.00          0.00
    db file scattered read                      32286        0.12        166.99
    db file sequential read                       111        0.01          0.07
    read by other session                       55408        0.05         58.57
    SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************
    (snip)
    =====================
    PARSING IN CURSOR #3 len=120 dep=0 uid=97 oct=3 lid=99 tim=9447508771750 hv=204457666 ad='7cdadae8'
    select  mod(lastinstmessagesequence, :"SYS_B_0") LastInstIDSeqNo from tibex_msgseqbyuseralias where useralias=:"SYS_B_1"
    END OF STMT
    PARSE #3:c=0,e=945,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=9447508771740
    =====================
    (snip)
    BINDS #3:
    kkscoacd
    Bind#0
    oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
    oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
    kxsbbbfp=fffffd7ffdbb2530  bln=22  avl=02  flg=09
    value=1000000000
    Bind#1
    oacdty=02 mxl=22(03) mxlc=00 mal=00 scl=00 pre=00
    oacflg=10 fl2=0300 frm=00 csi=00 siz=24 off=0
    kxsbbbfp=fffffd7ffdbb24e8  bln=22  avl=03  flg=09
    value=2228
    EXEC #3:c=20000,e=15877,p=1,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=9447508787670
    WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9447508787713
    WAIT #3: nam='db file scattered read' ela= 13221 file#=6 block#=214796 blocks=5 obj#=101804 tim=9447508972972
    WAIT #3: nam='db file scattered read' ela= 14568 file#=6 block#=905 blocks=8 obj#=101804 tim=9447508987786
    WAIT #3: nam='db file scattered read' ela= 32396 file#=6 block#=922 blocks=7 obj#=101804 tim=9447509020555
    WAIT #3: nam='read by other session' ela= 1772 file#=6 block#=890284 class#=1 obj#=101804 tim=9447683396281
    WAIT #3: nam='read by other session' ela= 2 file#=6 block#=890292 class#=1 obj#=101804 tim=9447683396555
    WAIT #3: nam='read by other session' ela= 1487 file#=6 block#=890292 class#=1 obj#=101804 tim=9447683398067
    WAIT #3: nam='read by other session' ela= 2 file#=6 block#=890300 class#=1 obj#=101804 tim=9447683398308
    WAIT #3: nam='read by other session' ela= 1528 file#=6 block#=890300 class#=1 obj#=101804 tim=9447683399849
    WAIT #3: nam='read by other session' ela= 4 file#=6 block#=890310 class#=1 obj#=101804 tim=9447683400173
    WAIT #3: nam='read by other session' ela= 1497 file#=6 block#=890310 class#=1 obj#=101804 tim=9447683401692
    WAIT #3: nam='read by other session' ela= 1 file#=6 block#=890318 class#=1 obj#=101804 tim=9447683401938
    WAIT #3: nam='read by other session' ela= 1368 file#=6 block#=890318 class#=1 obj#=101804 tim=9447683403318
    WAIT #3: nam='read by other session' ela= 1 file#=6 block#=890326 class#=1 obj#=101804 tim=9447683403562
    WAIT #3: nam='read by other session' ela= 2 file#=6 block#=1475577 class#=1 obj#=101804 tim=9447751022223
    WAIT #3: nam='read by other session' ela= 1289 file#=6 block#=1475577 class#=1 obj#=101804 tim=9447751023532
    FETCH #3:c=23680000,e=242256812,p=255454,cr=493346,cu=0,mis=0,r=0,dep=0,og=1,tim=9447751044552
    WAIT #3: nam='SQL*Net message from client' ela= 1200 driver id=1413697536 #bytes=1 p3=0 obj#=101804 tim=9447751045930
    STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY NOSORT (cr=493346 pr=255454 pw=0 time=242256982 us)'
    STAT #3 id=2 cnt=0 pid=1 pos=1 obj=0 op='VIEW  (cr=493346 pr=255454 pw=0 time=242256956 us)'
    STAT #3 id=3 cnt=0 pid=2 pos=1 obj=0 op='UNION-ALL  (cr=493346 pr=255454 pw=0 time=242256953 us)'
    STAT #3 id=4 cnt=0 pid=3 pos=1 obj=0 op='HASH GROUP BY (cr=9405 pr=0 pw=0 time=171791 us)'
    STAT #3 id=5 cnt=0 pid=4 pos=1 obj=101876 op='TABLE ACCESS FULL TIBEX_QUOTE (cr=9405 pr=0 pw=0 time=171536 us)'
    STAT #3 id=6 cnt=0 pid=3 pos=2 obj=0 op='HASH GROUP BY (cr=480896 pr=255454 pw=0 time=242064507 us)'
    STAT #3 id=7 cnt=0 pid=6 pos=1 obj=101804 op='TABLE ACCESS FULL TIBEX_ORDER (cr=480896 pr=255454 pw=0 time=242064378 us)'
    STAT #3 id=8 cnt=0 pid=3 pos=3 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=171 us)'
    STAT #3 id=9 cnt=0 pid=8 pos=1 obj=102015 op='TABLE ACCESS FULL TIBEX_TSTRADE (cr=3 pr=0 pw=0 time=41 us)'
    STAT #3 id=10 cnt=0 pid=3 pos=4 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=56 us)'
    STAT #3 id=11 cnt=0 pid=10 pos=1 obj=101710 op='TABLE ACCESS FULL TIBEX_IOIREQUEST (cr=3 pr=0 pw=0 time=12 us)'
    STAT #3 id=12 cnt=0 pid=3 pos=5 obj=0 op='HASH GROUP BY (cr=126 pr=0 pw=0 time=1139 us)'
    STAT #3 id=13 cnt=0 pid=12 pos=1 obj=101395 op='TABLE ACCESS FULL TIBEX_BESTEXREL (cr=126 pr=0 pw=0 time=1096 us)'
    STAT #3 id=14 cnt=0 pid=3 pos=6 obj=0 op='HASH GROUP BY (cr=2862 pr=0 pw=0 time=18123 us)'
    STAT #3 id=15 cnt=0 pid=14 pos=1 obj=101665 op='INDEX FAST FULL SCAN SYS_C0058325 (cr=2862 pr=0 pw=0 time=18042 us)'
    STAT #3 id=16 cnt=0 pid=3 pos=7 obj=0 op='HASH GROUP BY (cr=31 pr=0 pw=0 time=808 us)'
    STAT #3 id=17 cnt=0 pid=16 pos=1 obj=407076 op='TABLE ACCESS FULL TIBEX_EDPPULLORDERS (cr=31 pr=0 pw=0 time=746 us)'
    STAT #3 id=18 cnt=0 pid=3 pos=8 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=27 us)'
    STAT #3 id=19 cnt=0 pid=18 pos=1 obj=101851 op='INDEX FULL SCAN SYS_C0058803 (cr=1 pr=0 pw=0 time=21 us)'
    STAT #3 id=20 cnt=0 pid=3 pos=9 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)'
    STAT #3 id=21 cnt=0 pid=20 pos=1 obj=101398 op='INDEX FULL SCAN SYS_C0057785 (cr=1 pr=0 pw=0 time=7 us)'
    STAT #3 id=22 cnt=0 pid=3 pos=10 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=23 cnt=0 pid=22 pos=1 obj=101406 op='INDEX FULL SCAN SYS_C0057827 (cr=1 pr=0 pw=0 time=4 us)'
    STAT #3 id=24 cnt=0 pid=3 pos=11 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=40 us)'
    STAT #3 id=25 cnt=0 pid=24 pos=1 obj=101497 op='TABLE ACCESS FULL TIBEX_DELETEADMIN (cr=3 pr=0 pw=0 time=18 us)'
    STAT #3 id=26 cnt=0 pid=3 pos=12 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)'
    STAT #3 id=27 cnt=0 pid=26 pos=1 obj=101576 op='INDEX FULL SCAN SYS_C0058148 (cr=1 pr=0 pw=0 time=8 us)'
    STAT #3 id=28 cnt=0 pid=3 pos=13 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=29 cnt=0 pid=28 pos=1 obj=101642 op='INDEX FULL SCAN SYS_C0058264 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=30 cnt=0 pid=3 pos=14 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)'
    STAT #3 id=31 cnt=0 pid=30 pos=1 obj=101740 op='INDEX FULL SCAN SYS_C0058516 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=32 cnt=0 pid=3 pos=15 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=33 cnt=0 pid=32 pos=1 obj=101759 op='INDEX FULL SCAN SYS_C0058561 (cr=1 pr=0 pw=0 time=4 us)'
    STAT #3 id=34 cnt=0 pid=3 pos=16 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)'
    STAT #3 id=35 cnt=0 pid=34 pos=1 obj=101842 op='INDEX FULL SCAN SYS_C0058783 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=36 cnt=0 pid=3 pos=17 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)'
    STAT #3 id=37 cnt=0 pid=36 pos=1 obj=101947 op='INDEX FULL SCAN SYS_C0058977 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=38 cnt=0 pid=3 pos=18 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=11 us)'
    STAT #3 id=39 cnt=0 pid=38 pos=1 obj=101884 op='INDEX FULL SCAN SYS_C0058859 (cr=1 pr=0 pw=0 time=6 us)'
    STAT #3 id=40 cnt=0 pid=3 pos=19 obj=0 op='SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=13 us)'
    STAT #3 id=41 cnt=0 pid=40 pos=1 obj=102043 op='INDEX FULL SCAN SYS_C0059197 (cr=1 pr=0 pw=0 time=8 us)'
    STAT #3 id=42 cnt=0 pid=3 pos=20 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=35 us)'
    STAT #3 id=43 cnt=0 pid=42 pos=1 obj=101423 op='TABLE ACCESS FULL TIBEX_CANCELTRDADMIN (cr=3 pr=0 pw=0 time=17 us)'
    STAT #3 id=44 cnt=0 pid=3 pos=21 obj=0 op='HASH GROUP BY (cr=3 pr=0 pw=0 time=33 us)'
    STAT #3 id=45 cnt=0 pid=44 pos=1 obj=186696 op='TABLE ACCESS FULL TIBEX_BULKCANCELADMIN (cr=3 pr=0 pw=0 time=12 us)'
    (snip)
    Very helpful. The execution plan has changed. Notice that the second bind variable listed is 2228 rather than '2221' that was specified earlier. oacdty=02 for that bind variable indicates that the value is actually a number, while the SQL statement specifies the value as a VARCHAR2 (this likely will not be a problem, Oracle just performs an implicit VARCHAR2 to NUMBER conversion). Keep in mind that the SQL statement was likely optimized for a bind value of 2221, and that might not be appropriate for the bind variable value of 2228.

    A partial comparison of the execution plans:
    -------------------------------------------------------------------------------------------------------------------
    | Id  | Operation                       | Name                  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
    -------------------------------------------------------------------------------------------------------------------
    |   1 |  SORT GROUP BY NOSORT           |                       |      1 |     21 |      0 |00:00:00.11 |    8561 | SORT GROUP BY NOSORT (cr=493346 pr=255454 pw=0 time=242256982 us)
    |   2 |   VIEW                          |                       |      1 |     21 |      0 |00:00:00.11 |    8561 |  VIEW  (cr=493346 pr=255454 pw=0 time=242256956 us)
    |   3 |    UNION-ALL                    |                       |      1 |        |      0 |00:00:00.11 |    8561 |   UNION-ALL  (cr=493346 pr=255454 pw=0 time=242256953 us)
    |   4 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.09 |    5512 |    HASH GROUP BY (cr=9405 pr=0 pw=0 time=171791 us)
    |*  5 |      TABLE ACCESS FULL          | TIBEX_QUOTE           |      1 |  21056 |      0 |00:00:00.09 |    5512 |     TABLE ACCESS FULL TIBEX_QUOTE (cr=9405 pr=0 pw=0 time=171536 us)
    |   6 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       4 |    HASH GROUP BY (cr=480896 pr=255454 pw=0 time=242064507 us)
    |   7 |      TABLE ACCESS BY INDEX ROWID| TIBEX_ORDER           |      1 |    660 |      0 |00:00:00.01 |       4 |     TABLE ACCESS FULL TIBEX_ORDER (cr=480896 pr=255454 pw=0 time=242064378 us)
    |*  8 |       INDEX RANGE SCAN          | TIBEX_ORDER_IDX_OLT   |      1 |    660 |      0 |00:00:00.01 |       4 |   <---^ note that the index was not used in 10046, full table scan of TIBEX_ORDER 
    |   9 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       3 |    HASH GROUP BY (cr=3 pr=0 pw=0 time=171 us)
    |* 10 |      TABLE ACCESS FULL          | TIBEX_TSTRADE         |      1 |      1 |      0 |00:00:00.01 |       3 |
    |  11 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       3 |
    |* 12 |      TABLE ACCESS FULL          | TIBEX_IOIREQUEST      |      1 |      1 |      0 |00:00:00.01 |       3 |
    |  13 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |     126 |
    |* 14 |      TABLE ACCESS FULL          | TIBEX_BESTEXREL       |      1 |      1 |      0 |00:00:00.01 |     126 |
    |  15 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.02 |    2862 |
    |* 16 |      INDEX FAST FULL SCAN       | SYS_C0058325          |      1 |    339 |      0 |00:00:00.02 |    2862 |
    |  17 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |      31 |
    |* 18 |      TABLE ACCESS FULL          | TIBEX_EDPPULLORDERS   |      1 |      1 |      0 |00:00:00.01 |      31 |
    |  19 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 |
    |* 20 |      INDEX RANGE SCAN           | SYS_C0058803          |      1 |      1 |      0 |00:00:00.01 |       1 |
    |  21 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 |
    |* 22 |      INDEX RANGE SCAN           | SYS_C0057785          |      1 |      1 |      0 |00:00:00.01 |       1 |
    |  23 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 |
    |* 24 |      INDEX RANGE SCAN           | SYS_C0057827          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0057827 (cr=1 pr=0 pw=0 time=4 us)(object id 101406)
    |  25 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       3 | HASH GROUP BY (cr=3 pr=0 pw=0 time=40 us)
    |* 26 |      TABLE ACCESS FULL          | TIBEX_DELETEADMIN     |      1 |      1 |      0 |00:00:00.01 |       3 |  TABLE ACCESS FULL TIBEX_DELETEADMIN (cr=3 pr=0 pw=0 time=18 us)
    |  27 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=12 us)
    |* 28 |      INDEX RANGE SCAN           | SYS_C0058148          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058148 (cr=1 pr=0 pw=0 time=8 us)(object id 101576)
    |  29 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    |* 30 |      INDEX RANGE SCAN           | SYS_C0058264          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058264 (cr=1 pr=0 pw=0 time=6 us)(object id 101642)
    |  31 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)
    |* 32 |      INDEX RANGE SCAN           | SYS_C0058516          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058516 (cr=1 pr=0 pw=0 time=6 us)(object id 101740)
    |  33 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    |* 34 |      INDEX RANGE SCAN           | SYS_C0058561          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058561 (cr=1 pr=0 pw=0 time=4 us)(object id 101759)
    |  35 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=9 us)
    |* 36 |      INDEX RANGE SCAN           | SYS_C0058783          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058783 (cr=1 pr=0 pw=0 time=6 us)(object id 101842)
    |  37 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=10 us)
    |* 38 |      INDEX RANGE SCAN           | SYS_C0058977          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058977 (cr=1 pr=0 pw=0 time=6 us)(object id 101947)
    |  39 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=11 us)
    |* 40 |      INDEX RANGE SCAN           | SYS_C0058859          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0058859 (cr=1 pr=0 pw=0 time=6 us)(object id 101884)
    |  41 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       1 | SORT GROUP BY NOSORT (cr=1 pr=0 pw=0 time=13 us)
    |* 42 |      INDEX RANGE SCAN           | SYS_C0059197          |      1 |      1 |      0 |00:00:00.01 |       1 |  INDEX FULL SCAN SYS_C0059197 (cr=1 pr=0 pw=0 time=8 us)(object id 102043)
    |  43 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       3 | HASH GROUP BY (cr=3 pr=0 pw=0 time=35 us)
    |* 44 |      TABLE ACCESS FULL          | TIBEX_CANCELTRDADMIN  |      1 |      1 |      0 |00:00:00.01 |       3 |  TABLE ACCESS FULL TIBEX_CANCELTRDADMIN (cr=3 pr=0 pw=0 time=17 us)
    |  45 |     SORT GROUP BY NOSORT        |                       |      1 |      1 |      0 |00:00:00.01 |       3 | HASH GROUP BY (cr=3 pr=0 pw=0 time=33 us)
    |* 46 |      TABLE ACCESS FULL          | TIBEX_BULKCANCELADMIN |      1 |      1 |      0 |00:00:00.01 |       3 |  TABLE ACCESS FULL TIBEX_BULKCANCELADMIN (cr=3 pr=0 pw=0 time=12 us)
    -------------------------------------------------------------------------------------------------------------------
    You might need an index hint in the view to make certain that the TIBEX_ORDER_IDX_OLT index is always used, or disable cursor sharing.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 26. Re: Query Takes more Time when i execute from the Instant client.
    CharlesHooper Expert
    Currently Being Moderated
    Sorry, I posted the previous response before it was complete.

    Please retrieve the execution plan for the query from the library cache. Based on the raw 10046 trace file, the HASH_VALUE for this query is 204457666, so the following should retrieve the execution plan formatted by DBMS_XPLAN, showing predicted cardinality:
    SET PAGESIZE 1000
    SET LINESIZE 140
     
    SELECT
      *
    FROM
      TABLE(DBMS_XPLAN.DISPLAY_CURSOR(
        (SELECT
          SQL_ID
        FROM
          V$SQL
        WHERE
          HASH_VALUE= 204457666),NULL,'TYPICAL'));
    The following may return the same information as the above, but please post it any way:
    SET PAGESIZE 1000
    SET LINESIZE 140
     
    SELECT
      *
    FROM
      TABLE(DBMS_XPLAN.DISPLAY_CURSOR(
        (SELECT
          SQL_ID
        FROM
          V$SQL
        WHERE
          HASH_VALUE= 204457666),NULL,'ALLSTATS LAST'));
    If you see odd output like the following, that probably means that the execution plan has aged out of the shared pool:
    SQL_ID  dyk4dprp70d74, child number 0
    -------------------------------------
    SELECT DECODE('A','A','1','2') FROM DUAL
    
    Plan hash value: 1388734953
    
    -----------------------------------------------------------------
    | Id  | Operation        | Name | Rows  | Cost (%CPU)| Time     |
    -----------------------------------------------------------------
    |   0 | SELECT STATEMENT |      |       |     2 (100)|          |
    |   1 |  FAST DUAL       |      |     1 |     2   (0)| 00:00:01 |
    -----------------------------------------------------------------
     
    -or something like this-
    SQL_ID  bnjj99q60x7mu, child number 0
    -------------------------------------
    SELECT   * FROM   TABLE(DBMS_XPLAN.DISPLAY_CURSOR(     (SELECT
    SQL_ID     FROM       V$SQL     WHERE       HASH_VALUE=
    204457666),NULL,'ALLSTATS LAST'))
    
    Plan hash value: 3713220770
    
    ------------------------------------------------------------
    | Id  | Operation                         | Name           |
    ------------------------------------------------------------
    |   1 |  COLLECTION ITERATOR PICKLER FETCH| DISPLAY_CURSOR |
    ------------------------------------------------------------
    
    Note
    -----
       - rule based optimizer used (consider using cbo)
       - Warning: basic plan statistics not available. These are only collected when:
           * hint 'gather_plan_statistics' is used for the statement or
           * parameter 'statistics_level' is set to 'ALL', at session or system level
    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 27. Re: Query Takes more Time when i execute from the Instant client.
    NM Newbie
    Currently Being Moderated
    Hi Charles,

    The Statements were aged out.I have quick Question.

    1.How does the optimizer find the Table has Stale Stats.

    In our Env i find Stale for Most of the Transaction tables(Tibex_order).

    1.In the beginning of the Day the Table has 200 records in the Main Transaction tables

    2.At 10 am it will be around 1 million

    3.At 1 pm it will be around 5 million(During this period if user does the Query it will take atleast 3 to 4 min to retrieve the data).So if i run the sqlextract(sqlt) it shows me as Tibex_Order has Stale stats.So how to avoid this kind of problem.

    4.At 4 pm it will around 10 million records

    5.We will generate the complete stats on this table(Tibex_order)

    6.After EOD process it will truncate the Tibex_order.

    Kindly Answer

    What is the best solution if you have this kind of ENV w.r.t statistics.

    Outline
    Dynamic Sampling

    Regards
    NM
  • 28. Re: Query Takes more Time when i execute from the Instant client.
    CharlesHooper Expert
    Currently Being Moderated
    NM wrote:
    Hi Charles,

    The Statements were aged out.I have quick Question.
    Interesting.
    1.How does the optimizer find the Table has Stale Stats.
    From http://download.oracle.com/docs/cd/B19306_01/appdev.102/b14258/d_stats.htm :
    "GATHER STALE: Gathers statistics on stale objects as determined by looking at the *_tab_modifications views. Also, return a list of objects found to be stale."

    From http://download.oracle.com/docs/cd/B19306_01/server.102/b14211/stats.htm#i41282 :
    "Optimizer statistics are automatically gathered with the job GATHER_STATS_JOB. This job gathers statistics on all objects in the database which have:
    •Missing statistics
    •Stale statistics

    This job is created automatically at database creation time and is managed by the Scheduler. The Scheduler runs this job when the maintenance window is opened. By default, the maintenance window opens every night from 10 P.M. to 6 A.M. and all day on weekends."

    So, according to the above the DBMS_STATS routine will look at either ALL_TAB_MODIFICATIONS or DBA_TAB_MODIFICATIONS to determine which objects have experienced significant changes (such as a truncate or changes to more than 10% of the rows).
    In our Env i find Stale for Most of the Transaction tables(Tibex_order).

    1.In the beginning of the Day the Table has 200 records in the Main Transaction tables

    2.At 10 am it will be around 1 million

    3.At 1 pm it will be around 5 million(During this period if user does the Query it will take atleast 3 to 4 min to retrieve the data).So if i run the sqlextract(sqlt) it shows me as Tibex_Order has Stale stats.So how to avoid this kind of problem.

    4.At 4 pm it will around 10 million records

    5.We will generate the complete stats on this table(Tibex_order)

    6.After EOD process it will truncate the Tibex_order.

    Kindly Answer

    What is the best solution if you have this kind of ENV w.r.t statistics.

    Outline
    Dynamic Sampling

    Regards
    NM
    Outlines will lock an execute plan so that the same plan in used when the table contains 200 rows as is used when it contains 10,000,000 rows. Should the same plan always be used?

    Dynamic sampling only takes effect when a hard parse happens - and typically (by default) only for tables without statistics. CURSOR_SHARING is either set to FORCE or SIMILAR, so even if the literals (constants) change throughout the day, the execution plan will remain the same until a couple of hours after the nightly statistics collection job finds that there are 0 rows in the table due to the TRUNCATE.

    If you want to keep the execution plan the same, you could manually set the statistics on the table, and then lock those statistics. If you want to have the execution plan change throughout the day, that is more difficult. You will have to set the correct statistics and then some how force a hard parse of the SQL statement. I wonder if calling several times a day DBMS_STATS.GATHER_TABLE_STATS for the table with NO_INVALIDATE set to FALSE, and ESTIMATE_PERCENT set to a reasonable value (maybe a low percentage to decrease the impact on the database performance during statistics collection) would be sufficient to allow the execution plan to change as needed throughout the day.

    Someone else might have much better suggestions.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 29. Re: Query Takes more Time when i execute from the Instant client.
    user503699 Expert
    Currently Being Moderated
    Charles Hooper wrote:
    Someone else might have much better suggestions.
    I believe it all depends upon how those data volumes OP mentioned are generated and how the data is queried.
    If the data is loaded in bulk, then gathering statistics after the data load makes sense as it gives optimizer enough
    information to generate best plans for queries.
    However, if the data is generated by large number of small DMLs (possibly using some application), it may not be feasible
    to collect stats during the day. If the data volumes at different times of the day can be predicted close to actual data and
    if optimizer decideds to change plans for queries, then selective use of stored outlines might help.
    But I guess it all boils down to
    a) how the data is populated
    b) how the data is queried
    c) Frequency of the above
    d) Business priority of data usage vs. data creation/update
    Hope this helps.

    p.s. BTW, Those table names and data patterns look very familier. ;)

Legend

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