This discussion is archived
1 2 Previous Next 15 Replies Latest reply: Apr 20, 2011 6:55 AM by Dom Brooks RSS

performance tuning

844366 Newbie
Currently Being Moderated
hello,

we are having development database 10gR2...


one of the query is taking more than around 2mints...

all the tables being accessed in this query have been analyzed recently with dbms_stats package...


the query is and the trace output is
SELECT   Distinct  Patient.PatientId, Patient.Registration_No AS RegistrationNo, Visit.VisitNo,
    Patient.First_Name || '''' || Patient.Middle_Name || '''' || Patient.Last_Name AS PatientName, OrderMst.OrdNo,
    OrderMst.OrdDateTime, OrderMst.OrdId,Fn_GetLabTestNameOrderWise(OrderMst.OrdId) as "Test Name"
    FROM Patient INNER JOIN
    Visit ON Patient.PatientId = Visit.PatientID INNER JOIN
    OrderMst ON Visit.Visit_ID = OrderMst.OrdVisitID INNER JOIN
    OrderDtl ON OrderMst.OrdId = OrderDtl.OrdID
        WHERE  OrderMst.OrdId IN     (SELECT OrderDtl.OrdID
                                  FROM OrderDtl INNER JOIN
                                                Service_Mst ON OrderDtl.ServiceId = Service_Mst.Service_ID
                                  WHERE Service_Mst.category_Id in ( 30,32) 
                                  and    Service_Mst.SubDepartmentId IN (SELECT SubDetartmentID
                                                                          FROM UserDepartment
                                                                          WHERE UserID = 1)
                                  And nvl(OrderDtl.IsOutsourced, 0) in (1,2)
                                  AND nvl(OrderDtl.ReportAuthorization, 0) = 0
                                  AND nvl(OrderDtl.Cancelled, 0) = 0)
          and OrderMst.locid=  '1' ;
and the trace is
3407 rows selected



---------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |                |     1 |   188 |  3397   (5)| 00:00:41 |
|   1 |  HASH UNIQUE                     |                |     1 |   188 |  3397   (5)| 00:00:41 |
|   2 |   NESTED LOOPS                   |                |     1 |   188 |  3396   (5)| 00:00:41 |
|   3 |    NESTED LOOPS                  |                |     1 |   183 |  3394   (5)| 00:00:41 |
|   4 |     NESTED LOOPS                 |                |     1 |   135 |  3393   (5)| 00:00:41 |
|   5 |      NESTED LOOPS                |                |     1 |   101 |  3392   (5)| 00:00:41 |
|*  6 |       HASH JOIN                  |                |     1 |    52 |  3391   (5)| 00:00:41 |
|*  7 |        HASH JOIN                 |                |     1 |    38 |     8  (13)| 00:00:01 |
|*  8 |         TABLE ACCESS FULL        | USERDEPARTMENT |     1 |    26 |     2   (0)| 00:00:01 |
|*  9 |         TABLE ACCESS FULL        | SERVICE_MST    |    66 |   792 |     5   (0)| 00:00:01 |
|* 10 |        TABLE ACCESS FULL         | ORDERDTL       |   160K|  2194K|  3380   (5)| 00:00:41 |
|* 11 |       TABLE ACCESS BY INDEX ROWID| ORDERMST       |     1 |    49 |     1   (0)| 00:00:01 |
|* 12 |        INDEX UNIQUE SCAN         | PK_ORDERMST    |     1 |       |     0   (0)| 00:00:01 |
|  13 |      TABLE ACCESS BY INDEX ROWID | VISIT          |     1 |    34 |     1   (0)| 00:00:01 |
|* 14 |       INDEX UNIQUE SCAN          | PK_VISIT       |     1 |       |     0   (0)| 00:00:01 |
|  15 |     TABLE ACCESS BY INDEX ROWID  | PATIENT        |     1 |    48 |     1   (0)| 00:00:01 |
|* 16 |      INDEX UNIQUE SCAN           | SYS_C0021762   |     1 |       |     0   (0)| 00:00:01 |
|* 17 |    INDEX RANGE SCAN              | IX_ORDID       |     5 |    25 |     2   (0)| 00:00:01 |

 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   6 - access("ORDERDTL"."SERVICEID"="SERVICE_MST"."SERVICE_ID")
   7 - access("SERVICE_MST"."SUBDEPARTMENTID"="SUBDETARTMENTID")
   8 - filter("USERID"=1)
   9 - filter(("SERVICE_MST"."CATEGORY_ID"=30 OR "SERVICE_MST"."CATEGORY_ID"=32) AND 
              "SERVICE_MST"."SERVICE_ID">=0)
  10 - filter((NVL("ORDERDTL"."ISOUTSOURCED",0)=1 OR NVL("ORDERDTL"."ISOUTSOURCED",0)=2) 
              AND NVL("ORDERDTL"."REPORTAUTHORIZATION",0)=0 AND NVL("ORDERDTL"."CANCELLED",0)=0)
  11 - filter("ORDERMST"."LOCID"='1')
  12 - access("ORDERDTL"."ORDID"="ORDERMST"."ORDID")
  14 - access("VISIT"."VISIT_ID"="ORDERMST"."ORDVISITID")
  16 - access("PATIENT"."PATIENTID"="VISIT"."PATIENTID")
  17 - access("ORDERMST"."ORDID"="ORDERDTL"."ORDID")

   Statistics
-----------------------------------------------------------
           71213  recursive calls
               0  db block gets
         1819753  consistent gets
           15632  physical reads
               0  redo size
               0  workarea executions - multipass
               0  parse time cpu
               0  parse time elapsed
               0  frame signature mismatch
           71215  execute count
the statistics shows that 15632 blocks are being read from the disk so do i need to keep anything in buffer ...??

to be frank ii dont know what to do.........


i need you people help on this ...

thank you very much
  • 1. Re: performance tuning
    729964 Newbie
    Currently Being Moderated
    you can think of indexing orderid on
    TABLE ACCESS FULL | ORDERDTL | 160K| 2194K| 3380
  • 2. Re: performance tuning
    FahdMirza Oracle ACE
    Currently Being Moderated
    Why that response time is unacceptable? Was this query running in less response time earlier?

    regards
  • 3. Re: performance tuning
    844366 Newbie
    Currently Being Moderated
    hello Fahad,

    2 to 3 mints is quit unacceptable as this query fetches only 3k rows..

    is there any concern over the statistics shown....

    thank you
  • 4. Re: performance tuning
    sybrand_b Guru
    Currently Being Moderated
    You should disregard the physical reads, and notice the high number of consistent gets.
    If you change the cache it will only reduce physical reads, however the number of consistent gets won't reduce, and the statement would remain inefficient.
    The problem is at step 10, where orderdtl needs to undergo a full table scan, as there are no suitable indices.
    Your usage of nvl precludes the use of an index, also null values are not being indexed anyway.

    This predicate is very strange
    And nvl(OrderDtl.IsOutsourced, 0) in (1,2)

    SQL has three valued logic, true, false, and NULL. The above predicate signifies you don't want the NULLs (0 is always not equal to 1 and 2), so you should be able to leave out the nvl, and index that column, assuming most values are NULL (otherwise indexing the column probably won't help).

    -----------
    Sybrand Bakker
    Senior Oracle DBA
  • 5. Re: performance tuning
    844366 Newbie
    Currently Being Moderated
    hello sybrand,,

    after having done the changes in query ,,,now its taking more than before

    what to do now?

    shall i truncate all the relevant table and see the result then?

    shall i cache the related table in keep pool???


    thank you...
  • 6. Re: performance tuning
    Carlovski Pro
    Currently Being Moderated
    As sybrand was telling you, don't worry about the physical reads for now, reduce the physical reads by reducing the logical ones. If in the end you have a large number of unavoidable reads that are having to go to disk, then you might want to look at buffer cache type tuning, but it's not the first step.
    The first run may well be slower - apart from the parsing, it will have to read that new index. What about repeated executions?
    How selective is that index anyway? What percentage of rows in that table have an IsOutsourced value of 1 or 2?

    Anyway, I was more interested in the number of execution and recursive calls in there. What if you remove the calls to OrderMst.OrdId,Fn_GetLabTestNameOrderWise(OrderMst.OrdId) and just return the OrdId?
    Even then the numbers don't add up - unless the Fn_GetLabTestNameOrderWise function itself is calling further functions (In a where clause perhaps?)
  • 7. Re: performance tuning
    Dom Brooks Guru
    Currently Being Moderated
    What you have a provided is only half of the information you need.
    Your execution plan shows you the expected rows.

    You can see from these estimates that this select is expected to return 1 row.
    You have already said that the select returns something like 3000 rows.

    So, there is a clear and significant inaccuracy in the optimizer's estimates.

    Compare to estimates from your explain plan to the actuals either by doing a SQL TRACE (alter session set sql_trace = true) and running the trace file through TKPROF or run the SQL (run, don't explain plan, don't autotrace, etc) with the /*+ gather_plan_statistics */ hint and then fetch the execution plan via
    SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
    This will give you a nicely formatted output where you can compare ACTUAL rows vs ESTIMATES.
    Then focus on the improving the estimates.

    All this information and more is available in the tuning threads:

    How to post a SQL tuning request - HOW TO: Post a SQL statement tuning request - template posting
    When your query takes too long - When your query takes too long ...
  • 8. Re: performance tuning
    TakhteJamshid Newbie
    Currently Being Moderated
    Hi

    * Try to eliminate Full Table Scans by creating appropriate Indexes

    * Notice to using NVL function as you use , It can cause that the optimizer doesn't use Indexes

    * In some situations replacing IN by EXISTS can cause batter performance for example
    select * from t1 where t1.num in (select num from t2) ----> select * from t1 where exists (select 1 from t2 where t1.num=t2.num)

    * verify Fn_GetLabTestNameOrderWise it can be problem to you

    * use "SQL Tuning Advisor" it may gives good advices to you

    * Use ADDM for finding your database bottlenecks and refine them

    * Verify your database SGA configuration and your tables/indexes buffer pools

    * Maybe using Materialized Views be good to you

    * It may that you do some tuning on your script and because you have many data in your tables it takes long time to run
    many things depend on the nature of your application for example in some conditions you can move unnecessary rows to another tables or a Data warehouse for increasing speed of your query
  • 9. Re: performance tuning
    844366 Newbie
    Currently Being Moderated
    hi dom,

    here is my tracefile output
    TKPROF: Release 10.2.0.3.0 - Production on Wed Apr 20 15:57:08 2011
    
    Copyright (c) 1982, 2005, Oracle.  All rights reserved.
    
    Trace file: C:\oracle\product\10.2.0\db_1\admin\orcl\udump\orcl_ora_21552.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   Distinct  Patient.PatientId, Patient.Registration_No AS RegistrationNo, Visit.VisitNo,
        Patient.First_Name || '''' || Patient.Middle_Name || '''' || Patient.Last_Name AS PatientName, OrderMst.OrdNo,
        OrderMst.OrdDateTime, OrderMst.OrdId,Fn_GetLabTestNameOrderWise(OrderMst.OrdId) as "Test Name"
        FROM Patient INNER JOIN
        Visit ON Patient.PatientId = Visit.PatientID INNER JOIN
        OrderMst ON Visit.Visit_ID = OrderMst.OrdVisitID INNER JOIN
        OrderDtl ON OrderMst.OrdId = OrderDtl.OrdID
            WHERE  OrderMst.OrdId IN     (SELECT OrderDtl.OrdID
                                      FROM OrderDtl INNER JOIN
                                                    Service_Mst ON OrderDtl.ServiceId = Service_Mst.Service_ID
                                      WHERE Service_Mst.category_Id in ( 30,32) 
                                      and    Service_Mst.SubDepartmentId IN (SELECT SubDetartmentID
                                                                              FROM UserDepartment
                                                                              WHERE UserID = 1)
                                      And nvl(OrderDtl.IsOutsourced,0) in (1,2)
                                      AND nvl(OrderDtl.ReportAuthorization,0)=0 
                                      AND nvl(OrderDtl.Cancelled,0)=0)
              and OrderMst.locid=  '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        8     12.23      14.65      16160      19376          0        3429
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       10     12.23      14.65      16160      19376          0        3429
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 62  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
       3429  HASH UNIQUE (cr=1072306 pr=16161 pw=0 time=269352564 us)
      71288   HASH JOIN  (cr=19376 pr=16160 pw=0 time=2798931 us)
       5439    HASH JOIN  (cr=17486 pr=15941 pw=0 time=2153773 us)
       3428     TABLE ACCESS FULL PATIENT (cr=221 pr=0 pw=0 time=10367 us)
      15183     HASH JOIN  (cr=17265 pr=15941 pw=0 time=2154360 us)
      15185      HASH JOIN  (cr=16401 pr=15940 pw=0 time=2030586 us)
      15185       HASH JOIN  (cr=14763 pr=14316 pw=0 time=2959457 us)
        212        HASH JOIN  (cr=42 pr=0 pw=0 time=18079 us)
         26         TABLE ACCESS FULL USERDEPARTMENT (cr=23 pr=0 pw=0 time=230 us)
        377         TABLE ACCESS FULL SERVICE_MST (cr=19 pr=0 pw=0 time=19223 us)
      21498        TABLE ACCESS FULL ORDERDTL (cr=14721 pr=14316 pw=0 time=1249340 us)
      84025       TABLE ACCESS FULL ORDERMST (cr=1638 pr=1624 pw=0 time=264941 us)
      17560      TABLE ACCESS FULL VISIT (cr=864 pr=1 pw=0 time=52739 us)
     445637    INDEX FAST FULL SCAN IX_ORDID (cr=1890 pr=219 pw=0 time=1339168 us)(object id 76178)
    
    ********************************************************************************
    
    SELECT DISTINCT :B2 + ',' + NVL(SERVICE_MST.SERVICE_NAME, '') 
    FROM
     ORDERDTL JOIN SERVICE_MST ON ORDERDTL.SERVICEID = SERVICE_MST.SERVICE_ID 
      WHERE CATEGORY_ID = 30 AND ORDID = :B1 
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute  71288      8.06       8.33          0          0          0           0
    Fetch    71288    142.89     246.35          0    1052926          0       71288
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   142577    150.95     254.69          0    1052926          0       71288
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 62     (recursive depth: 1)
    ********************************************************************************
    
    select condition 
    from
     cdef$ 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          0          2          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.00          0          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: 2)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=28 us)
    
    ********************************************************************************
    
    select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, 
      sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, 
      spare1, spare2, avgcln 
    from
     hist_head$ where obj#=:1 and intcol#=:2
    
    
    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.01          1          2          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.01          1          2          0           0
    
    Misses in library cache during parse: 0
    Optimizer mode: RULE
    Parsing user id: SYS   (recursive depth: 3)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=2 pr=1 pw=0 time=10706 us)
          0   INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=1 pw=0 time=10692 us)(object id 257)
    
    ********************************************************************************
    
    SELECT object_type type, user owner, object_name, null column_name 
    FROM all_objects 
    WHERE rownum <=20 and object_name not like 'BIN$%'  and object_type IN ('PROCEDURE', 'PACKAGE') 
     and object_name like :1 
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        2      0.00       0.00          0          0          0           0
    Execute      2      0.01       0.03          0          0          0           0
    Fetch        2      0.00       0.09         22        136          0           6
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        6      0.01       0.12         22        136          0           6
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 62  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  TABLE ACCESS BY INDEX ROWID SUM$ (cr=0 pr=0 pw=0 time=0 us)
          0   INDEX UNIQUE SCAN I_SUM$_1 (cr=0 pr=0 pw=0 time=0 us)(object id 398)
          6  COUNT STOPKEY (cr=101 pr=22 pw=0 time=124577 us)
          6   FILTER  (cr=101 pr=22 pw=0 time=124546 us)
         56    HASH JOIN  (cr=89 pr=19 pw=0 time=75541 us)
         56     TABLE ACCESS BY INDEX ROWID OBJ$ (cr=82 pr=19 pw=0 time=1683 us)
         56      INDEX SKIP SCAN I_OBJ2 (cr=36 pr=4 pw=0 time=561 us)(object id 37)
         92     TABLE ACCESS FULL USER$ (cr=7 pr=0 pw=0 time=44 us)
          0    TABLE ACCESS BY INDEX ROWID SUM$ (cr=0 pr=0 pw=0 time=0 us)
          0   INDEX UNIQUE SCAN I_SUM$_1 (cr=0 pr=0 pw=0 time=0 us)(object id 398)
          0    TABLE ACCESS BY INDEX ROWID IND$ (cr=0 pr=0 pw=0 time=0 us)
          0     INDEX UNIQUE SCAN I_IND1 (cr=0 pr=0 pw=0 time=0 us)(object id 39)
          0    NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us)
          0     INDEX RANGE SCAN I_OBJAUTH1 (cr=0 pr=0 pw=0 time=0 us)(object id 103)
          0     FIXED TABLE FULL X$KZSRO (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    VIEW  (cr=0 pr=0 pw=0 time=0 us)
          0     FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0    FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
    
    ********************************************************************************
    
    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          0          3          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.00          0          3          0           1
    
    Misses in library cache during parse: 0
    Optimizer mode: CHOOSE
    Parsing user id: SYS   (recursive depth: 1)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=23 us)
    
    ********************************************************************************
    
    SELECT 'SCHEMA' type, username owner, username object_name, null column_name 
    FROM all_users WHERE rownum <=20
     and username like :1 
     union all 
    SELECT object_type type, user owner, object_name, null column_name 
    FROM all_objects 
    WHERE rownum <=20 and object_name not like 'BIN$%'  and object_type IN ('FUNCTION', 'PACKAGE') 
     and object_name like :2 
    
    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.03          3         37          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.03          3         37          0           0
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 62  
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          0  UNION-ALL  (cr=37 pr=3 pw=0 time=30209 us)
          0   COUNT STOPKEY (cr=1 pr=0 pw=0 time=75 us)
          0    NESTED LOOPS  (cr=1 pr=0 pw=0 time=61 us)
          0     NESTED LOOPS  (cr=1 pr=0 pw=0 time=50 us)
          0      TABLE ACCESS BY INDEX ROWID USER$ (cr=1 pr=0 pw=0 time=39 us)
          0       INDEX RANGE SCAN I_USER1 (cr=1 pr=0 pw=0 time=25 us)(object id 44)
          0      TABLE ACCESS CLUSTER TS$ (cr=0 pr=0 pw=0 time=0 us)
          0       INDEX UNIQUE SCAN I_TS# (cr=0 pr=0 pw=0 time=0 us)(object id 7)
          0     TABLE ACCESS CLUSTER TS$ (cr=0 pr=0 pw=0 time=0 us)
          0      INDEX UNIQUE SCAN I_TS# (cr=0 pr=0 pw=0 time=0 us)(object id 7)
          0   COUNT STOPKEY (cr=36 pr=3 pw=0 time=30095 us)
          0    FILTER  (cr=36 pr=3 pw=0 time=30081 us)
          0     NESTED LOOPS  (cr=36 pr=3 pw=0 time=30069 us)
          0      TABLE ACCESS BY INDEX ROWID OBJ$ (cr=36 pr=3 pw=0 time=30059 us)
          0       INDEX SKIP SCAN I_OBJ2 (cr=36 pr=3 pw=0 time=30046 us)(object id 37)
          0      TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)
          0       INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)(object id 11)
          0     TABLE ACCESS BY INDEX ROWID SUM$ (cr=0 pr=0 pw=0 time=0 us)
          0      INDEX UNIQUE SCAN I_SUM$_1 (cr=0 pr=0 pw=0 time=0 us)(object id 398)
          0     TABLE ACCESS BY INDEX ROWID IND$ (cr=0 pr=0 pw=0 time=0 us)
          0      INDEX UNIQUE SCAN I_IND1 (cr=0 pr=0 pw=0 time=0 us)(object id 39)
          0     NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us)
          0      INDEX RANGE SCAN I_OBJAUTH1 (cr=0 pr=0 pw=0 time=0 us)(object id 103)
          0      FIXED TABLE FULL X$KZSRO (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     VIEW  (cr=0 pr=0 pw=0 time=0 us)
          0      FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
          0     FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us)
    
    ********************************************************************************
    
    alter session set sql_trace=false
    
    
    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: 62  
    
    
    
    ********************************************************************************
    
    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        5      0.00       0.00          0          0          0           0
    Execute      5      0.01       0.03          0          0          0           0
    Fetch       11     12.23      14.78      16185      19549          0        3435
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       21     12.25      14.81      16185      19549          0        3435
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    
    
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        4      0.00       0.00          0          0          0           0
    Execute  71291      8.06       8.34          0          0          0           0
    Fetch    71291    142.89     246.36          1    1052933          0       71290
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   142586    150.95     254.71          1    1052933          0       71290
    
    Misses in library cache during parse: 2
    Misses in library cache during execute: 2
    
        6  user  SQL statements in session.
        3  internal SQL statements in session.
        9  SQL statements in session.
    ********************************************************************************
    Trace file: C:\oracle\product\10.2.0\db_1\admin\orcl\udump\orcl_ora_21552.trc
    Trace file compatibility: 10.01.00
    Sort options: default
    
           1  session in tracefile.
           6  user  SQL statements in trace file.
           3  internal SQL statements in trace file.
           9  SQL statements in trace file.
           8  unique SQL statements in trace file.
      142862  lines in trace file.
         361  elapsed seconds in trace file.
    now can someone help me out with this output and help me find out the real bottleneck ..

    thanks and regards
  • 10. Re: performance tuning
    Dom Brooks Guru
    Currently Being Moderated
    So your function Fn_GetLabTestNameOrderWise(OrderMst.OrdId) is what you need to sort out.
    That's where all the time is going - see trace.
  • 11. Re: performance tuning
    844366 Newbie
    Currently Being Moderated
    hi dom,
    your function Fn_GetLabTestNameOrderWise(OrderMst.OrdId) is what you need to sort out.
    That's where all the time is going - see trace.
    i am still unable to figure out where in trace ...

    can u tell me where did u noticed that in trace..

    thanks
  • 12. Re: performance tuning
    Dom Brooks Guru
    Currently Being Moderated
    Look in the trace above.

    See section for your main SQL statement:
    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        8     12.23      14.65      16160      19376          0        3429
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       10     12.23      14.65      16160      19376          0        3429
    Then see section below that
    SELECT DISTINCT :B2 + ',' + NVL(SERVICE_MST.SERVICE_NAME, '') 
    FROM
     ORDERDTL JOIN SERVICE_MST ON ORDERDTL.SERVICEID = SERVICE_MST.SERVICE_ID 
      WHERE CATEGORY_ID = 30 AND ORDID = :B1 
     
     
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute  71288      8.06       8.33          0          0          0           0
    Fetch    71288    142.89     246.35          0    1052926          0       71288
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   142577    150.95     254.69          0    1052926          0       71288
    So, your function is executed 71288 as part of step 2 in the main SQL plan above.
    71288   HASH JOIN  (cr=19376 pr=16160 pw=0 time=2798931 us)
    So, first step, before you do anything else, would be to do the DISTINCT before you call the function - that way you should save 67000 calls to the function as the only input parameter - OrdId - is part of the DISTINCT clause anyway.

    So, something like this (just banged out a quick example - I don't particularly like the ANSI style and mixing it with code that might be non-ANSI, etc) might help as long as the view isn't merged
    SELECT x.*, Fn_GetLabTestNameOrderWise(OrderMst.OrdId) as "Test Name"
    FROM    ((SELECT   Distinct  Patient.PatientId, Patient.Registration_No AS RegistrationNo, Visit.VisitNo,
        Patient.First_Name || '''' || Patient.Middle_Name || '''' || Patient.Last_Name AS PatientName, OrderMst.OrdNo,
        OrderMst.OrdDateTime, OrderMst.OrdId
        FROM Patient INNER JOIN
        Visit ON Patient.PatientId = Visit.PatientID INNER JOIN
        OrderMst ON Visit.Visit_ID = OrderMst.OrdVisitID INNER JOIN
        OrderDtl ON OrderMst.OrdId = OrderDtl.OrdID
            WHERE  OrderMst.OrdId IN     (SELECT OrderDtl.OrdID
                                      FROM OrderDtl INNER JOIN
                                                    Service_Mst ON OrderDtl.ServiceId = Service_Mst.Service_ID
                                      WHERE Service_Mst.category_Id in ( 30,32) 
                                      and    Service_Mst.SubDepartmentId IN (SELECT SubDetartmentID
                                                                              FROM UserDepartment
                                                                              WHERE UserID = 1)
                                      And nvl(OrderDtl.IsOutsourced,0) in (1,2)
                                      AND nvl(OrderDtl.ReportAuthorization,0)=0 
                                      AND nvl(OrderDtl.Cancelled,0)=0)
              and OrderMst.locid=  '1' ) x;
    Secondly, the execution plan for that function logic isn't listed, but you should also review it.
  • 13. Re: performance tuning
    844366 Newbie
    Currently Being Moderated
    hello dom... sorry...i must call you by Sir dom..really...

    now it has jumped down to only 15 secs from 6 mints....


    you are absolutely fantastic....
    you taught me a new thing...

    but still i am not able to understand

    SELECT DISTINCT :B2 + ',' + NVL(SERVICE_MST.SERVICE_NAME, '') 
    FROM
     ORDERDTL JOIN SERVICE_MST ON ORDERDTL.SERVICEID = SERVICE_MST.SERVICE_ID 
      WHERE CATEGORY_ID = 30 AND ORDID = :B1 
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute  71288      8.06       8.33          0          0          0           0
    Fetch    71288    142.89     246.35          0    1052926          0       71288
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   142577    150.95     254.69          0    1052926          0       71288
    how did you know that this is the function call? i mean how did you now that in this part of the trace my function Fn_GetLabTestNameOrderWise(OrderMst.OrdId) is being called, though this code does not tell us the name of the function...

    plz give me a hint so that in future i can figure out by looking at the trace output that some function is being called ..

    also
    SELECT x.*, Fn_GetLabTestNameOrderWise(x.OrdId) as "Test Name"
    FROM    (SELECT   Distinct  Patient.PatientId, Patient.Registration_No AS RegistrationNo, Visit.VisitNo,
        Patient.First_Name || '''' || Patient.Middle_Name || '''' || Patient.Last_Name AS PatientName, OrderMst.OrdNo,
        OrderMst.OrdDateTime, OrderMst.OrdId
        FROM Patient INNER JOIN
        Visit ON Patient.PatientId = Visit.PatientID INNER JOIN
        OrderMst ON Visit.Visit_ID = OrderMst.OrdVisitID INNER JOIN
        OrderDtl ON OrderMst.OrdId = OrderDtl.OrdID
            WHERE  OrderMst.OrdId IN     (SELECT OrderDtl.OrdID
                                      FROM OrderDtl INNER JOIN
                                                    Service_Mst ON OrderDtl.ServiceId = Service_Mst.Service_ID
                                      WHERE Service_Mst.category_Id in ( 30,32) 
                                      and    Service_Mst.SubDepartmentId IN (SELECT SubDetartmentID
                                                                              FROM UserDepartment
                                                                              WHERE UserID = 1)
                                      And nvl(OrderDtl.IsOutsourced,0) in (1,2)
                                      AND nvl(OrderDtl.ReportAuthorization,0)=0 
                                      AND nvl(OrderDtl.Cancelled,0)=0)
              and OrderMst.locid=  '1' ) x;
    what was the effect of x here...do i need to use your x factor where the functions are bineg used..
    i must know this things cause there are many query in which function is being called

    thanks and regards a lot...
  • 14. Re: performance tuning
    Carlovski Pro
    Currently Being Moderated
    It's fairly obvious,
               71213  recursive calls
                   0  db block gets
             1819753  consistent gets
               15632  physical reads
                   0  redo size
                   0  workarea executions - multipass
                   0  parse time cpu
                   0  parse time elapsed
                   0  frame signature mismatch
               71215  execute count
    The number of recursive calls tells us that some more sql is being called over the sql we were running directly.You will always get some recursive calls for the optimizer, but here it is obvious something is running per row. The usual suspect is a function call in a where clause, but here is was in the select, which isn't normally too bad, but the fact you had a large intermediate results set, and then had to distinct it had the same effect.

    You can't tell directly from the trace (As far as I am aware) the name of the subprogram that generated the SQL, but it should be fairly obvious by looking at the source of any functions being called inline by the SQL. It can get tricky when you have nested calls, or are using lots of views using functions, but was easy in this case.

    I would say though that having to do the distinct implies that you may have something wrong with your query, I don't know the logic or what you are trying to do, but I'm guessing you should be grouping by something like visit or order.

    Carl
1 2 Previous Next

Legend

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