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.
Mohamed Houri’s Oracle Notes 