Mohamed Houri’s Oracle Notes

September 14, 2012

Tuning by TKPROF: a case study

Filed under: Tuning — hourim @ 11:21 am

One of our end users complains about a query that was suffering a performance pain. He sent me the query statement and its corresponding “tkrpofed” 10046 trace events and asked for help. This blog article represents a summary of my step by step tuning investigations of this performance problem

First of all what can we diagnose just with the following bit of information extracted from the tkprof trace?

 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.02       0.02          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch       44     34.35     420.94     132860     161300          0         624
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       48     34.37     420.96     132860     161300          0         624

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS	
Parsing user id: 122  

Nothing?

Not really. Several important information can be derived from the above trace file

1. We have almost the same number of physical reads (132860) and buffer reads (161300). This is a clear symptom of and a pointer to the presence of aggressive full table scans that should be investigated
2. There is a big difference between elapsed time (420.96 s) and CPU time (43.37). This means that the query spent a large amount of time waiting for something that should be investigated
3. The query used a big number of physical and logical read in order to generate a limited number of 624 rows via 2 executions. This means that this query starts by selecting a big number of rows and then threw away a large amount of this initial big number of selected rows. This is in contradiction with the mantra ‘’start small and keep small’’
4. There was one miss in library cache during parse which means that a hard parse have been done during the execution of the query

So, have you noticed how much of information we can diagnose simply by looking at those 4 lines of trace file? In fact there is still another important information which can be derived from the above 4 lines that I have preferred to ignore for the moment. We will be back to it in a moment.

Let’s continue the investigation using the next part of tkprof trace file. What can we derive from the following bit of information?

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      46        0.00          0.00
  SQL*Net message from client                    46      128.81        387.60
  db file scattered read                       4844        1.28        387.95
  db file sequential read                        76        0.72          1.89

Nothing?

Not really. Oracle spent 387,95 seconds generating data through full table scan (db file scattered read, remember what I’ve said above about the number of physical and logical I/O) and about 387,60 seconds waiting for the client to ask this generated data (SQL*Net message from client) in 46 batches(Times Waited) of 15 rows

You might ask from where I have derived that number of 15 rows per client/server round trip? This is the information which can be immediately derived from the first 4 lines of trace and that I’ve preferred to delay it until this section.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.02       0.02          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch       44     34.35     420.94     132860     161300          0         624
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       48     34.37     420.96     132860     161300          0         624

Oracle generated 624 rows using 2 executions and 44 fetches:

rows/Fetch = 624/44=14,18 ~ 15

This number represent the default arraysize the query used to exchange information between the server and the client:

So, the time Oracle spent generating data equals the time it waited for the client to ask for it!!! This is a symptom of a problem in the network activity. Changing the default arraysize from its default value of 15 to a higher value might help enhancing the response time of this query.

Look how much information we’ve already collected and remember: we still have not yet investigated the content of the SQL query!!!

Let’s continue our tkprof trace file investigation. What can we identify from the tkprof row source operation reproduced here below?

Rows     Row Source Operation
-------  ---------------------------------------------------
    312  HASH JOIN OUTER (cr=80650 pr=66430 pw=0 time=216,681,765 us)
    312   VIEW  (cr=40325 pr=33215 pw=0 time=114,999,408 us)
    312    MERGE JOIN CARTESIAN (cr=40325 pr=33215 pw=0 time=114,999,403 us)
     26     VIEW  (cr=40325 pr=33215 pw=0 time=114,998,980 us)
     26      HASH GROUP BY (cr=40325 pr=33215 pw=0 time=114,998,974 us)
  19827       HASH JOIN SEMI (cr=40325 pr=33215 pw=0 time=114,911,666 us)
  45426        PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,077,047 us)
  45426         TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,031,597 us)
1721227        PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7670 us)
1721227         TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7646 us)
    312     BUFFER SORT (cr=0 pr=0 pw=0 time=208 us)
     12      VIEW  (cr=0 pr=0 pw=0 time=72 us)
     12       UNION-ALL  (cr=0 pr=0 pw=0 time=54 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=3 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=2 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=2 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=1 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=1 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=1 us)
    136   VIEW  (cr=40325 pr=33215 pw=0 time=101,678,318 us)
    136    SORT GROUP BY (cr=40325 pr=33215 pw=0 time=101,678,162 us)
  19827     HASH JOIN  (cr=40325 pr=33215 pw=0 time=101,446,253 us)
  45426      PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,613 us)
  45426       TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,597 us)
1721227      PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=1,729,734 us)
1721227       TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=8491 us)

The row source operation represents the real execution plan followed by Oracle during the execution of the query. Let me divide (divide to conquer) this explain plan into 2 mains parts:

part 1

    312   VIEW  (cr=40325 pr=33215 pw=0 time=114,999,408 us)
    312    MERGE JOIN CARTESIAN (cr=40325 pr=33215 pw=0 time=114,999,403 us)
     26     VIEW  (cr=40325 pr=33215 pw=0 time=114,998,980 us)
     26      HASH GROUP BY (cr=40325 pr=33215 pw=0 time=114,998,974 us)
  19827       HASH JOIN SEMI (cr=40325 pr=33215 pw=0 time=114,911,666 us)
  45426        PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,077,047 us)
  45426         TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,031,597 us)
1721227        PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7670 us)
1721227         TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7646 us)
    312     BUFFER SORT (cr=0 pr=0 pw=0 time=208 us)
     12      VIEW  (cr=0 pr=0 pw=0 time=72 us)
     12       UNION-ALL  (cr=0 pr=0 pw=0 time=54 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=3 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=2 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=2 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=1 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=1 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=0 us)
      1        FAST DUAL  (cr=0 pr=0 pw=0 time=1 us)

part 2

     136  VIEW  (cr=40325 pr=33215 pw=0 time=101,678,318 us)
    136    SORT GROUP BY (cr=40325 pr=33215 pw=0 time=101,678,162 us)
  19827     HASH JOIN  (cr=40325 pr=33215 pw=0 time=101,446,253 us)
  45426      PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,613 us)
  45426       TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,597 us)
1721227      PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=1,729,734 us)
1721227       TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=8491 us)

The two parts are hash joined together via the first operation

Rows     Row Source Operation
-------  ---------------------------------------------------
    312  HASH JOIN OUTER (cr=80650 pr=66430 pw=0 time=216,681,765 us)

Producing 312 rows in 216 seconds. Multiply this by 2 executions and you will have the image reported by the tkprof summary i.e. 624 rows in 420 seconds.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.02       0.02          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch       44     34.35     420.94     132860     161300          0         624
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       48     34.37     420.96     132860     161300          0         624

If I look carefully to both part1 and part2 I can easily point out that the most consuming operations are:

Rows     Row Source Operation
-------  ------------------------------------------------------------------------------------------------------
45426         TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,031,597 us)
45426       TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,597 us)

Which are consuming 112 and 98 seconds respectively.Well, only 2 operations generating 200 seconds while the entire row source shows a total time of 216 seconds. It is clear that reviewing those two table scans will help enhancing the performance of your query.

You might have already pointed out the MERGE JOIN CARTESIAN operation done on a built table generating 26 rows. I will be back to this later in a new post.

What else? Do we have reached the point at which the SQL query content became essential?
Not really. But we are very close to the border of that necessity. Looking at the number of rows generated by this table access full operation (45426), an immediate question came to my mind: how many rows are there in this table?

  select Count(*) from ORDERS_MANAGMENTS  ----> 8,999,341 

Spot the obvious: the full scan operation is selecting 45426 records from a table having 8,999,341 records using a FULL TABLE SCAN!!! 0,005% of records via a FULL TABLE SCAN. Something is wrong here, isn’t it?
And now we can’t go further ahead without asking the content of the query and other information related to the table and its indexes. But that will be dealt with in the next post.

17 Comments »

  1. Hi Mohamed.

    Using TKPROF you found problematic are, actually where time spend,consume, this is good. But what is a next? How we can reduce this time and avoid waiting?
    And if it is really need tune (if it is a problem 420 second elapsed time) user need provide ORACLE version , query it self(table and index structure) and explain plan (with real and estimated rows). After that we can discusses and can think about that.

    Comment by Chinar Aliyev — September 14, 2012 @ 1:23 pm | Reply

  2. Hi Chinar,

    Next would be to understand why the query used a full scan operation to generate 0,005% of data. For that we need to look at the query, its execution plan (with E-Rows as you’ve mentioned) to the predicate part of the execution plan and spot where things start going wrong : (a) lack of statistics, (b) absence of suitable index (c) implicit conversion etc…

    Best regards

    Comment by hourim — September 14, 2012 @ 1:29 pm | Reply

  3. Good walk through Mohammed and certainly knowledge refreshing (not doing much trace nowadays sticking with sql monitoring )

    As regular reader can I also request if you can give full feed instead of truncated feed for your RSS feeds. It would really help us (who reads on the go ) to read on our RSS readers and it will also help you getting misleading information for dual hit counts as rss feed is one hit count then me visiting the site is another🙂 Wish you take my request into consideration.

    Thank you very much

    Comment by coskan — September 16, 2012 @ 12:21 pm | Reply

  4. Hi Coskan,

    Thanks a lot for being a regular reader of my blog. I like very much what you’ve already published in your blog also.

    Without any hesitation, I will take into account your suggestion.

    Best regards

    Comment by Mohamed — September 16, 2012 @ 1:22 pm | Reply

  5. Hi Mohamed, I come from Oracle forum, and in my case I commented:

    From the overall results:

    – I do not have the same number of physical reads (871,088) and buffer reads (2,798,882).

    – If there is a big difference between elapsed time (4685.59 s) and CPU time (226.29)

    – In total:
    – Execute 111405
    – Rows 122 222

    – 8245 Misses in library cache During parse

    I have not:

    SQL * Net message to client
    SQL * Net message from client
    db file scattered read
    db file sequential read

    rows / fetch = 122222/46033 = 2.65

    TABLE ACCESS FULL:

    RLS 224 TABLE ACCESS FULL $ (cr = 168 pr = 2 pw = 0 time = 14027 us)
    RLS 224 TABLE ACCESS FULL $ (cr = 168 pr = 0 pw = 0 time = 1637 us)
    38 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 189 pr = 6 pw = 0 time = 22413 us)
    0 TABLE ACCESS FULL GDCTIE (cr = 3 pr = 1 pw = 0 time = 18613 us)
    360 TABLE ACCESS FULL HISRDEBUG_DAT (cr = 2520 pr = 0 pw = 0 time = 15164 us)
    0 TABLE ACCESS FULL AREA (cr = 7 pr = 5 pw = 0 time = 16151 us)
    39 TABLE ACCESS FULL HISRDEVICERANGE (cr = 210 pr = 0 pw = 0 time = 1675 us)
    1890 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 210 pr = 0 pw = 0 time = 17048 us)
    27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 168 pr = 0 pw = 0 time = 1740 us)
    1512 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 168 pr = 0 pw = 0 time = 12108 us)
    27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 168 pr = 6 pw = 0 time = 8647 us)
    0 TABLE ACCESS FULL DYNAMICSCHEDULE (cr = 3 pr = 1 pw = 0 time = 8621 us)
    1 TABLE ACCESS FULL DUAL (cr = 3 pr = 2 pw = 0 time = 5037 us)
    8206 TABLE ACCESS FULL TEMPDEVTABLE1 (cr = 16 pr = 0 pw = 0 time = 41 us)
    8 TABLE ACCESS FULL RLS $ (cr = 3 pr = 0 pw = 0 time = 64 us)
    12 TABLE ACCESS FULL HISRDEVICERANGE (cr = 42 pr = 0 pw = 0 time = 337 us)
    378 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 42 pr = 0 pw = 0 time = 3317 us)
    27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 215 pr = 0 pw = 0 time = 1643 us)
    27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 168 pr = 0 pw = 0 time = 991 us)
    3 TABLE ACCESS FULL FIDEVICESETHELPER (cr = 21 pr = 6 pw = 0 time = 20396 us)

    Is the “time” in second units?

    As I can explain that the job run is 77 minutes ( = 4620 seconds ), if the time is in second units?

    Comment by carlos — March 26, 2013 @ 4:25 pm | Reply

  6. Carlos,

    *SELECT MAX(UTCTIME)* 
    *FROM*
     *CONECT_01 WHERE POINTNUMBER=:device_1*
     
     
    call         count       cpu       elapsed       disk      query     current    rows
    Parse        1776       0.05       0.03           0        0           0         0
    Execute      1776       0.04       0.11           0        0           0         0
    Fetch        3553       51.58      2256.05      405620    552615       0         1776 
    total        7105       51.67      2256.21      405620    552615       0         1776
    
    Rows     Execution Plan
          0  SELECT STATEMENT   MODE: ALL_ROWS
          0   SORT (AGGREGATE)
          0    FIRST ROW
          0     INDEX   MODE: ANALYZED (FULL SCAN (MIN/MAX)) OF 
                    'CONECT_01_PK' (INDEX (UNIQUE))
    

    Let me just try to interpret the above part of your trace file.
    The first fundamental remark I can point out is that you are doing a parse for each execution. Ideally you have to parse 1 and execute many. Here the ratio Parse/Execute = 1 which means then you parsed this query each and every time you executed it and that needs to be corrected. You are performing many soft parses which can alter the total query response time.

    The second remark is that you did 1776 executions to generate 1776 rows (1 row for each execution of the above query). The question to ask is why when using a UNIQUE INDEX you did 405620/1776 = 228 physical read and 552615/1776 = 311 logical reads?

    I will try to model a case in order to approach your situation and if I will be successful I will write a dedicated blog article

    Comment by hourim — March 27, 2013 @ 12:10 pm | Reply

  7. Thanks Muhammed, I hope that your example can be usefull for me!

    ” Here the ratio Parse/Execute = 1 which means then you parsed this query each and every time you executed it and that needs to be corrected ”

    Could you, with the test model, to give to me an idea about how to improve the performance of the job execution?

    Regards!

    Comment by carlos — March 27, 2013 @ 6:40 pm | Reply

  8. S, is also part of the job description family nurse practitioner modern medical care system.

    How the patient should be C. For job description family nurse practitioner what reason choose an online
    program.

    Comment by family nurse practitioner practice questions — June 30, 2013 @ 1:11 pm | Reply

  9. Hi Hourim,

    Having subscribed to your posts , I read this post earlier but came back to read again today after I came across a sql query given by app team. The tkprof shows the number of fetches equal to the number of rows retrieved. Could you please suggest what might have caused this scenario. I executed the query from sqlplus. There are no wait events except SQL*Net message from client ( 55195 times). The query is taking around 20 minutes with almost entirely on CPU .

    I am sorry , I haven’t provided complete row source operation as it is very lengthy.

    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.13       0.13          0        108          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch    55194   1343.69    1347.19       1023   35180489  191237191       55193
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total    55196   1343.83    1347.33       1023   35180597  191237191       55193
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 87
    Number of plan statistics captured: 1
    
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
         55193      55193      55193  UNION-ALL  (cr=35180489 pr=1023 pw=1023 time=1340064555 us)
             1          1          1   FAST DUAL  (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
         55192      55192      55192   HASH JOIN RIGHT OUTER (cr=26613 pr=1023 pw=1023 time=6319276 us cost=4802851 size=3534719759588 card=35809861)
    

    Thank you again for your time

    Regards
    Rakesh

    Comment by rakeshchemikala — July 23, 2014 @ 8:56 pm | Reply

  10. Hi Rakesh,

    Is this a select statement? I presume yes because of the Fetch numbers. But if so why there is such a huge number of reads in current mode (191,237,191)?
    Current mode is generally for update statements. There are cases where we can observe current mode during select statements but not at this high number. Please clarify what type of statement you have tkprofed.

    Few comments about what you’ve posted:

    (a) 1 execution generates 55193 rows
    (b) 1 execution generates 35,180,489 logical I/O
    (c) 1 execution generates 191,237,191 current

    You have generated 55,193 rows using 55,194 fetches which represent an approximate array size of 1 (55193/55194 = 1) and you said that you’ve spent 20 minutes (1200 sec) waiting for the client (SQL*Net message from client) to ask for these rows. You might have a network issue. What if you try a different arraysize (set arraysize 500)

    Best regards

    Mohamed Houri

    Comment by hourim — July 24, 2014 @ 9:53 am | Reply

    • Hi Hourim,

      Thank you very much for replying so promptly, yes it is a select statement, I believe most of the consistent reads might be due to the lot of full table scans in the query. I have traced the query again with arraysize set to 500 , but the number of fetches still remain same as the rows retrieved. SQL* Net message from client wait event only accounts for 4-5 seconds (Max wait of 33 seconds is time taken for me to disable the trace after execution), here it seems most of the time is spent on CPU (during Fetch) .

      I agree that there are lot of full scans , I am also checking for proper indexes for these tables, but none of the full table scans have taken significant time as they are smaller tables. My apologies of any of my observations/assumptions doesn’t make sense.

      I have copied the entire row source operation below.

      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 55198 1359.74 1363.55 992 35182521 191249959 55197
      ——- —— ——– ———- ———- ———- ———- ———-
      total 55200 1359.74 1363.56 992 35182521 191249959 55197

      Misses in library cache during parse: 0
      Optimizer mode: ALL_ROWS
      Parsing user id: 87
      Number of plan statistics captured: 1

      Rows (1st) Rows (avg) Rows (max) Row Source Operation
      ———- ———- ———- —————————————————
      55197 55197 55197 UNION-ALL (cr=35182521 pr=992 pw=992 time=1357152667 us)
      1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
      55196 55196 55196 HASH JOIN RIGHT OUTER (cr=27189 pr=992 pw=992 time=6371550 us cost=4802851 size=3534719759588 card=35809861)
      7827 7827 7827 TABLE ACCESS FULL SII_ITEM_VENDOR_PART (cr=190 pr=0 pw=0 time=2101 us cost=68 size=801443 card=7781)
      55192 55192 55192 HASH JOIN RIGHT OUTER (cr=26999 pr=992 pw=992 time=6008196 us cost=4802467 size=3531031343905 card=35809861)
      26041 26041 26041 VIEW (cr=6306 pr=0 pw=0 time=2067281 us cost=12510 size=35097489504 card=1343496)
      26041 26041 26041 TRANSPOSE (cr=6306 pr=0 pw=0 time=2027567 us)
      1344007 1344007 1344007 SORT GROUP BY PIVOT (cr=6306 pr=0 pw=0 time=1915920 us cost=12510 size=38961384 card=1343496)
      1344007 1344007 1344007 TABLE ACCESS FULL SPOI_PRODUCT_CHARACTERISTICS (cr=6306 pr=0 pw=0 time=243596 us cost=1732 size=38961384 card=1343496)
      55192 55192 55192 HASH JOIN OUTER (cr=20693 pr=992 pw=992 time=3507860 us cost=738830 size=50523750822 card=697062)
      55192 55192 55192 HASH JOIN OUTER (cr=19935 pr=992 pw=992 time=2369564 us cost=360792 size=2414024890 card=196342)
      55192 55192 55192 HASH JOIN OUTER (cr=13535 pr=992 pw=992 time=948126 us cost=12895 size=158363324 card=35756)
      55192 55192 55192 HASH JOIN OUTER (cr=13157 pr=558 pw=558 time=689014 us cost=6993 size=12836404 card=35756)
      55192 55192 55192 HASH JOIN OUTER (cr=12082 pr=0 pw=0 time=327518 us cost=3975 size=8116612 card=35756)
      55192 55192 55192 HASH JOIN RIGHT OUTER (cr=996 pr=0 pw=0 time=60228 us cost=275 size=5577936 card=35756)
      35705 35705 35705 TABLE ACCESS FULL SPOI_PRODUCT_SUPPLY (cr=252 pr=0 pw=0 time=6369 us cost=69 size=1214412 card=35718)
      26042 26042 26042 HASH JOIN RIGHT OUTER (cr=744 pr=0 pw=0 time=35407 us cost=205 size=3175172 card=26026)
      16941 16941 16941 TABLE ACCESS FULL SPOI_PRODUCT_PRICING (cr=113 pr=0 pw=0 time=2082 us cost=32 size=524644 card=16924)
      26042 26042 26042 TABLE ACCESS FULL SPOI_PRODUCT (cr=631 pr=0 pw=0 time=15088 us cost=172 size=2368366 card=26026)
      160571 160571 160571 TABLE ACCESS FULL SII_XEROX_ITEM (cr=11086 pr=0 pw=0 time=191333 us cost=2787 size=11297023 card=159113)
      160571 160571 160571 VIEW VIEW_SII_ITEM_ALTERNATE (cr=1075 pr=558 pw=558 time=235352 us cost=1515 size=21196032 card=160576)
      160571 160571 160571 HASH GROUP BY PIVOT (cr=1075 pr=558 pw=558 time=210143 us cost=1515 size=4335552 card=160576)
      165381 165381 165381 TABLE ACCESS FULL SII_XEROX_ITEM_ALTERNATE (cr=1075 pr=0 pw=0 time=36513 us cost=276 size=4428783 card=164029)
      24937 24937 24937 VIEW VIEW_SPOI_PRODUCT_ALTERNATE (cr=378 pr=434 pw=434 time=102265 us cost=435 size=101945360 card=25048)
      24937 24937 24937 HASH GROUP BY PIVOT (cr=378 pr=434 pw=434 time=97785 us cost=435 size=926776 card=25048)
      49502 49502 49502 TABLE ACCESS FULL SPOI_PRODUCT_ALTERNATE (cr=378 pr=0 pw=0 time=9812 us cost=103 size=1831537 card=49501)
      160571 160571 160571 VIEW (cr=6400 pr=0 pw=0 time=1780491 us cost=11797 size=6936451182 card=881827)
      160571 160571 160571 TRANSPOSE (cr=6400 pr=0 pw=0 time=1646395 us)
      887026 887026 887026 SORT GROUP BY PIVOT (cr=6400 pr=0 pw=0 time=1471207 us cost=11797 size=39682215 card=881827)
      887482 887482 887482 TABLE ACCESS FULL SII_ITEM_CHARACTERISTICS (cr=6400 pr=0 pw=0 time=235982 us cost=1725 size=39682215 card=881827)
      3340 3340 3340 VIEW (cr=758 pr=0 pw=0 time=121934 us cost=947 size=5555107614 card=92299)
      3340 3340 3340 TRANSPOSE (cr=758 pr=0 pw=0 time=117358 us)
      58066 58066 58066 SORT GROUP BY PIVOT (cr=758 pr=0 pw=0 time=101540 us cost=947 size=2676671 card=92299)
      92299 92299 92299 TABLE ACCESS FULL SPOI_PRODUCT_ASSESSMENT (cr=758 pr=0 pw=0 time=17357 us cost=206 size=2676671 card=92299)

      Elapsed times include waiting on following events:
      Event waited on Times Max. Wait Total Waited
      —————————————- Waited ———- ————
      SQL*Net message to client 55199 0.00 0.04
      SQL*Net message from client 55199 33.10 37.09
      Disk file operations I/O 1 0.00 0.00
      asynch descriptor resize 6 0.00 0.00
      direct path write temp 32 0.00 0.10
      direct path read temp 32 0.00 0.00
      ********************************************************************************

      Please let me know your observations on having lot of fetches though we have tried arraysize 15(default sqlplus) and 500 as well.

      Thanks you again

      Regards
      Rakesh

      Comment by rakeshchemikala — July 24, 2014 @ 2:28 pm | Reply

      • Sorry , In my above reply , I meant current reads when I said “I believe most of the consistent reads”

        Comment by rakeshchemikala — July 24, 2014 @ 2:30 pm

  11. Hi Mohamed,

    I would like to add one of my other observation on the query. It has a function TO_CLOB(SP.OFFERINGITEMID) in select statement . I have removed to_clob function and traced the select again and the number of fetches decreased to 3681 ( 3681* 15 =55215) and current mode reads are only 8 now.

    Could you please let me know what does the function to_clob does to the number of rows a single fetch will retrieve and also to the current mode reads.

    Thank you

    Regards
    Rakesh

    Comment by rakeshchemikala — July 24, 2014 @ 7:16 pm | Reply

  12. Rakesh,

    I have tested a simple case and effectively when I used to_clob() the current info increased dramatically

    see below:

    -- select on simple varchar2 attribute
    select v,v,v from xtest
    where rownum <= 100
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          2          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.00       0.00          0        103          0         100
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4      0.00       0.00          0        105          0         100
    
    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 more data to client                    12        0.00          0.00
      SQL*Net message from client                     2       10.42         10.43
    ********************************************************************************
    

    And If I surround the v attribute with a to_clob(v) function the current info increased
    from 0 to 3595

    select to_clob(v),to_clob(v),to_clob(v) from xtest
    where rownum <= 100
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          3          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch      101      0.04       0.04          0        103       3595         100
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      103      0.05       0.05          0        106       3595         100
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                     102        0.00          0.00
      SQL*Net message from client                   102        1.18          1.26
      Disk file operations I/O                        1        0.00          0.00
    ********************************************************************************
    

    And if you do the same selects using sqlplus with autotrace stat set on you will remark a high number
    of SQL*Net roundtrips to/from client when using CLOB.

    I don’t know what you can do to reduce this SQL$Net roundtrips trafic time between the client and the sever. There is a simila discussion here that
    might helps

    https://mail.google.com/mail/u/0/#search/sayan/1474b4b13e9e251c

    Best regards

    Comment by hourim — July 25, 2014 @ 1:33 pm | Reply

    • Thanks Mohamed , I have asked app team if it is necessary to have to_clob function in their query, possibly will look for other options instead of the function.

      Thanks again for your help, will look forward for your new posts🙂

      PS: the url who have given is not working.

      Regards,
      Rakesh

      Comment by rakeshchemikala — July 25, 2014 @ 2:59 pm | Reply

    • Hello Mohammed,

      Hope you are doing good, I am asking you another question on trace after almost two years🙂 .
      We have enabled trace for one of application job after they had concern on its performance, after generating the trace I noticed the disk reads reported are 12551435 and CR reads 43399678 , but I couldn’t find anywhere in row source operation where that many logical/physical reads performed.
      May I know what could have been the reason to have mismatch between the total disk/logical reads reported in execute phase to the steps in row source operation. Also I am assuming the large no of logical reads contributed to the high CPU time during execution. Please correct if I am wrong.

      PS: I have set statistics_level = all at session level before running the job, tkprof was generated with sys=no.

      call count cpu elapsed disk query current rows
      ——- —— ——– ———- ———- ———- ———- ———-
      Parse 1 0.00 0.00 0 0 0 0
      Execute 29 1853.70 2383.55 12551435 43399678 200 8173
      Fetch 0 0.00 0.00 0 0 0 0
      ——- —— ——– ———- ———- ———- ———- ———-
      total 30 1853.70 2383.55 12551435 43399678 200 8173

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

      Rows (1st) Rows (avg) Rows (max) Row Source Operation
      ———- ———- ———- —————————————————
      0 0 0 LOAD TABLE CONVENTIONAL (cr=394906 pr=384280 pw=0 time=58013988 us)
      0 0 0 HASH GROUP BY (cr=394906 pr=384280 pw=0 time=58013959 us cost=238629 size=14742 card=182)
      0 0 0 NESTED LOOPS (cr=394906 pr=384280 pw=0 time=58013843 us cost=238628 size=14742 card=182)
      15028 15028 15028 HASH JOIN (cr=384229 pr=383730 pw=0 time=57532644 us cost=104686 size=4199202 card=85698)
      5 5 5 HASH JOIN (cr=470 pr=0 pw=0 time=15216 us cost=137 size=32 card=1)
      5 5 5 TABLE ACCESS FULL DEPT_TBL (cr=235 pr=0 pw=0 time=857 us cost=68 size=54 card=3)
      1579 1579 1579 VIEW VW_SQ_1 (cr=235 pr=0 pw=0 time=10740 us cost=69 size=22106 card=1579)
      1579 1579 1579 SORT GROUP BY (cr=235 pr=0 pw=0 time=9370 us cost=69 size=20527 card=1579)
      5992 5992 5992 TABLE ACCESS FULL DEPT_TBL (cr=235 pr=0 pw=0 time=3309 us cost=68 size=77896 card=5992)
      28422659 28422659 28422659 TABLE ACCESS FULL BI_HDR_AR (cr=383759 pr=383730 pw=0 time=19082047 us cost=104469 size=483181786 card=28422458)
      0 0 0 TABLE ACCESS BY INDEX ROWID BI_HDR (cr=10677 pr=550 pw=0 time=454573 us cost=2 size=32 card=1)
      823 823 823 INDEX UNIQUE SCAN BI_HDR (cr=9257 pr=88 pw=0 time=101081 us cost=1 size=0 card=1)(object id 643068)

      Elapsed times include waiting on following events:
      Event waited on Times Max. Wait Total Waited
      —————————————- Waited ———- ————
      Disk file operations I/O 30 0.00 0.00
      db file scattered read 196069 0.00 26.74
      db file sequential read 1423265 0.06 534.64

      *******************************************************************************

      Thanks
      Rakesh

      Comment by RakeshDBA — April 28, 2016 @ 4:18 pm | Reply

  13. Very Much IMP 4 Lines

    Comment by kanhaiya — April 2, 2015 @ 2:32 pm | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Create a free website or blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud Oracle's blog

Just another Oracle blog : Database topics and techniques

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

EU Careers info

Your career in the European Union

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)

%d bloggers like this: