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.

Advertisements

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)